ppi-socket 반복 로그 축소

마지막 업데이트 2026-09-08

d33d4c2b charles-na · 2026-09-08 Fix 12 files +951 −30

운영 로그를 실측해 반복 시그니처 4종을 줄인 커밋 4개다. 4시간 42,278줄 중 상위 5개 시그니처가 79.5%를 차지하고 있었고, 그중 상당수가 완전히 같은 값에 roomId조차 없는 상태였다.

가장 먼저 볼 지점은 줄인 것이 아니라 살린 것이다. transport 로그는 브라우저가 함께 보낸 rtt·비트레이트·손실률을 버리고 hasRtt 불린만 남기고 있었다. 축소와 함께 이 수치를 처음으로 기록한다.

이 문서는 같은 PR의 로그 추가 분량과 성격이 다른 커밋 4개(2a6525f2 7ede9cf6 c365ea3b 5e9e08c9)를 다룬다.

근거 — 운영 로그 실측

계획 문서의 1단계가 "근거 고정"이다. 추정으로 지우지 않기 위해 운영 로그 두 창을 집계했다.

시그니처	9/8 10–14시 (4h, 방 8개)	비율	판정 근거
Guest/Host transport state	11,537	27.3%	11,501줄(99.7%)이 동일 `{state:"connected",hasRtt:true}`. roomId·peerId 없음
[CAPTION-DIAG] 2종	8,019	19.0%	축소 대상 아님 — 아래 "발견" 참조
Transcript relay processed	7,204	17.0%	6,972줄(96.8%)이 동일 조합. roomId·전사 식별자 없음
guest_livekit_input_diagnostic	7,476	17.7%	traceHash로 상관관계 잡힘 → 보류. 단 `local_audio_level` 2,672줄은 1초 주기 덤프
Cleared manualReady	910	2.2%	방 7개뿐인데 한 방이 351회. 지울 상태 없어도 로깅
socket_speaking_rejected	445	1.1%	445줄 전부 동일. 전체 warn 509건의 87%

저녁 창은 훨씬 심하다. 9/8 16:45–16:52(7분) 16,995줄 = 분당 2,428줄로, 4시간 창(분당 176줄)의 약 14배다. 이 창이 유지되면 하루 350만 줄 규모다.

코드로 보는 핵심 지점

1. 버리고 있던 수치 — transport state

브라우저는 use-mediasoup-producer.ts:658에서 setInterval(emitState, 1000)으로 rtt·비트레이트·손실률을 실어 보낸다. 서버는 그것을 바로 다음 줄에서 모니터 payload로 쓰면서 로그에는 담지 않았다.

      apps/socket/src/sfu-socket/handlers/monitoring-handlers.ts
      -    logger.info("Guest transport state", {
      -      state,
      -      hasRtt: rtt !== undefined,   // ← 숫자를 버리고 불린만
      -      reason, code,
      -    });
      +    logTransportState({
      +      side: "guest", roomId: canonicalRoomId, peerId: canonicalPeerId, state,
      +      rtt, availableOutgoingBitrate, packetsLostRate,
      +      reason, code,
      +    });
       
           const canonicalPayload = { roomId, peerId, state, rtt,   // ← 여기선 원래 다 썼다
             availableOutgoingBitrate, packetsLostRate, ... };
    

2. 측정 시작을 품질 악화로 오분류한 자체 버그

구현 중 자체 리뷰에서 잡았다. 버킷 랭크에서 undefined를 -1로 두면, 세션 초반 rtt를 못 재던 구간(hasRtt:false)에서 재기 시작하는 순간이 rtt_degraded가 된다. 운영 로그에 그 전이가 실제로 8회 있어 매번 오탐이 찍힐 코드였다.

      apps/socket/src/sfu-socket/handlers/transport-state-log-gate.ts
      -function rankOf(bucket: TransportQualityBucket | undefined): number {
      -  return bucket === undefined ? -1 : BUCKET_RANK[bucket];
      -}
      +// 세션 초반에는 브라우저가 rtt·손실률을 못 실어 보낸다. 측정 가능해진 것을
      +// 품질 악화로 분류하면 안 되므로 별도 트리거로 한 번만 남긴다.
      +if (
      +  (entry.rttBucket === undefined) !== (rttBucket === undefined) ||
      +  (entry.lossBucket === undefined) !== (lossBucket === undefined)
      +) {
      +  return "metrics_availability_change";
      +}
      +// 버킷 비교는 양쪽이 모두 측정된 경우에만
    

3. rollup이 "이미 본 조합" 기억까지 지우던 문제

집계 모듈에서 counts와 seen을 함께 비우면, 다음 창의 첫 샘플이 first_seen으로 잘못 분류돼 창마다 최초 발생이 반복 보고된다. 테스트가 먼저 잡았다.

      apps/socket/src/sfu-socket/handlers/categorical-log-aggregator.ts
      +// rollup 창마다 비우는 누적치와, 창을 넘어 유지하는 "이미 본 조합"을 나눈다.
      +// 함께 비우면 다음 창의 첫 샘플이 최초 발생으로 잘못 분류된다.
      +  counts: Map<string, number>;   // rollup 시 clear
      +  seen: Set<string>;            // 창을 넘어 유지
    

4. 정상 동작을 warn으로 부르던 자리

SpeakingRelayGuard.stop()이 null 하나로 세 가지 거절을 뭉쳐 반환했다. 그중 no_active_turn(start 없는 stop)은 guard가 의도대로 막은 정상이다.

      apps/socket/src/sfu-socket/handlers/speaking-payload.ts
      -  stop(payload): SpeakingPayload | null {
      -    if (!active) return null;
      -    if (active.clientHadTrace && !payload.trace?.turnId) return null;
      -    if (turnId mismatch) return null;              // ← 셋을 구분할 수 없다
      +  stop(payload): SpeakingStopResult {
      +    if (!active) return { rejection: "no_active_turn" };        // 정상 → debug
      +    if (...) return { rejection: "trace_missing_on_stop" };   // 이상 → warn
      +    if (...) return { rejection: "turn_id_mismatch" };        // 이상 → warn
    

5. 지울 게 없어도 남기던 로그

clearManualReady는 게스트 발화 시작마다 호출된다(session-speaking-handlers.ts:83).

      apps/socket/src/mediasoup/room-state-manager.ts
      +    // 발화 시작마다 호출되므로, 지울 상태가 없을 때 로그를 남기면
      +    // 같은 방에서 수백 줄이 반복된다. 실제 전이만 기록한다.
      +    if (!room || room.manualReady == null) return;
           room.manualReady = null;
           logger.info(`Cleared manualReady for room ${roomId}`);
    

축소 정책 — 무엇을 남기는가

error/warn을 일괄 삭제하지 않았다. 최초 발생 + 상태 변화 + 최종 결과 + 반복 횟수를 보존하는 것이 조건이었다.

대상	남기는 조건	반복분 처리
transport state	`initial` / `state_change` / `reason_change` / `code_change` / `metrics_availability_change` / 품질 버킷 악화·회복 / `heartbeat`(5분)	`suppressedCount`로 합산 보고
전사 중계	조합의 최초 발생, 그리고 녹음 중 오디오 전사가 캡션에서 빠지는 경우는 매번	5분 rollup 창의 `counts`
발화 중단 거절	`trace_missing_on_stop`·`turn_id_mismatch`는 warn 유지 + 실제 ID 기록	`no_active_turn`은 debug 강등
manualReady	실제 전이	no-op 호출은 미기록

품질 버킷은 실제 rtt 분포를 알 수 없어(기존 로그에 rtt가 없었다) 보수적으로 넓게 잡았다 — rtt 150/300/600ms, 손실률 0.02/0.05/0.1(RTCP fractionLost 0~1 기준). 이 로그가 rtt를 남기기 시작한 뒤 실측으로 재조정할 값이다.

검증 — 스테이징 실기기 확인

같은 운영 로그를 게이트 로직에 재생한 예상치와, 스테이징 배포 후 실제 로그를 비교했다.

대상	재생 예상	운영 비율 (미반영)	스테이징 비율 (반영)
transport state	11,537 → 약 475 (95.9%↓)	27.3%	3.5%
전사 중계	7,204 → 약 70 (99.0%↓)	17.0~20.0%	0.5%
Cleared manualReady	실제 전이만	2.2~2.9%	상위 30 밖
socket_speaking_rejected	실제 오류만	warn의 87%	상위 30 밖

스테이징 로그(2026-09-08 18:05–18:15, 1,383줄)에서 신규 필드가 실제로 찍힘을 확인했다.

      ppi-socket-staging — Guest transport state
      {"roomId":"c28c8b32…_1","peerId":"guest-c28c8b32…_1","state":"connected",
       "rtt":8,"availableOutgoingBitrate":3311466,"packetsLostRate":0,
       "rttBucket":"ok","lossBucket":"ok",
       "trigger":"metrics_availability_change","suppressedCount":0}
      ppi-socket-staging — Transcript relay processed
      {"roomId":"…","peerId":"…","hasRecording":true,"isCaptionEligible":true,
       "transcriptRole":"assistant","transcriptType":"audio","contentLength":1,
       "reason":"first_seen","category":"assistant:audio:recording:caption"}
    

trigger 분포는 state_change 19 / metrics_availability_change 16 / initial 13이었다. rtt_degraded가 0건이므로 위 2번 오분류 픽스가 실기기에서 동작한다. 15분 창에 heartbeat가 없는 것은 스테이징 세션이 짧아 상태 변화가 계속 타이머를 리셋했기 때문이다.

자동 검증: socket build·tsc 통과, 신규 테스트 추가로 passed 711 → 727. 사전 존재 실패 17건(isRedisEnabled mock 누락, 5f61cfd6에서 유입되어 develop에 포함)은 불변이며 이 변경과 무관하다.

조사 중 발견 — 로그가 아니라 데이터 중복

[CAPTION-DIAG] caption turn appended 7,125줄은 축소하지 않았다. 파고들었더니 로그가 아니라 캡션 데이터 자체가 중복이었다. 이 로그를 줄이면 결함을 보이게 해주던 유일한 창구가 사라진다.

      브라우저 TRANSCRIPT_UPDATE (응답 하나에 스트리밍으로 여러 번)
              ↓
      session-diagnostic-handlers.ts  appendCaptionTurn() 매번 호출
              ↓
      recordingManager.ts:838  session.captionTurns.push(turn)   ← logId 중복 검사 없음
              ↓
      recordingManager.ts:1426  session.captionTurns.map(...)    ← 여기도 dedup 없음
              ↓
      caption.json 업로드
    

방	업로드된 caption 항목 수	녹음 길이
`…f08e_87`	2,861	25분
`…7ad31_44`	1,947	24분
`…1858_10`	1,722	20분

고유 logId 374개에서 7,125번 append됐다(중복 94.8%, 한 logId 최대 141회). startWallMs는 같고 endWallMs만 밀리므로 같은 발화가 시각만 다르게 수백 번 겹쳐 들어간다.

선행 확인: S3의 실제 caption.json에서 중복 항목의 message가 점진적으로 완성되는 형태인지 확인해야 dedup 정책(마지막 것으로 갱신 vs 첫 것만 유지)이 정해진다. 별도 티켓이 필요하다.

반영 여부 판별법

스테이징·운영 로그에서 축소가 적용됐는지는 줄 수가 아니라 필드로 판별한다. 트래픽 양이 창마다 14배까지 차이나기 때문이다.

확인 대상	반영됐다면
`Guest transport state`	`trigger`·`rttBucket`·`roomId`·`suppressedCount` 존재. 이전엔 `{state, hasRtt}`뿐
`Transcript relay processed`	`reason: "first_seen"` 또는 `"rollup"` + `category`. rollup이면 `counts`
`socket_speaking_rejected`	`no_active_turn`이 warn에서 사라짐. 남은 warn엔 실제 `roomId`·`peerId`
`Cleared manualReady`	방당 몇 건으로 감소

리뷰 관전 포인트

동작 확인

운영 배포 후 실제 감소율은 다시 측정해야 한다. 스테이징은 세션이 짧아 heartbeat와 rollup이 거의 나오지 않았다. 운영에서는 5분 heartbeat × 활성 키 수가 바닥값이 된다.

튜닝

품질 버킷 임계치는 rtt 분포를 모른 채 잡은 초기값이다. 스테이징 관측치가 rtt:8(ok)로 나왔으니, 운영 데이터가 쌓이면 elevated 경계가 적절한지 재검토가 필요하다.

관측성 감소

no_active_turn을 debug로 내렸으므로, 운영 로그 레벨이 debug를 버리면 그 445줄은 완전히 사라진다. 의도한 것이지만 "동작 무변경"과는 별개다.

구조

게이트와 집계 모듈이 TTL·항목 상한 로직을 비슷하게 갖는다. 의미가 달라(상태 전이 vs 조합 계수) 분리했지만 공통화 후보다. 게이트는 소켓 단위라 소켓과 함께 소멸한다.

영향 범위

브라우저의 1초 전송 간격, 모니터로 나가는 canonicalPayload, relay 동작과 payload는 모두 그대로다. SpeakingRelayGuard.stop() 시그니처만 바뀌었고 호출부 1곳과 기존 계약 테스트를 함께 갱신했다(null 확인 → 구체 사유 확인으로 강화).

미착수

guest_livekit_input_diagnostic(17.7%)은 보류했다. diagnosticTraceHash로 상관관계가 잡히는 의도된 계측이지만, 그중 local_audio_level 2,672줄과 local_input_media_health 813줄은 1초 주기 덤프라 변화 시점만 남기면 충분하다.