LiveKit agent readiness 타임아웃 — 워커 디스패치 즉시 포기 원인 분석 분석PR #1027

요약

LIVEKIT_CLIENT_SESSION | LiveKit agent readiness wait failed 로 AI 세션이 시작되지 못한 사건. 전체 워커 풀에는 빈 슬롯이 11개 있었지만, 그 job 을 처리한 LiveKit 노드에 등록된 워커 11개는 전부 꽉 차 있었다. 그중 3개만 아직 WS_AVAILABLE 로 보고된 상태(막 채워져 status 미갱신)라 후보가 됐고, 셋 다 실제로는 꽉 차서 거절하자 후보가 고갈돼 job 이 폐기됐다. 클라이언트는 통보를 못 받고 10초 뒤 스스로 타임아웃했다.

1. 증상과 범위

2026-08-25 기술이슈 일일 리포트에서 LiveKit agent readiness wait 가 긴급으로 2건 잡혔으나, 원본 세션 로그를 열어 보면 실제로는 3건이다. 최시원 세션은 대표 시그니처가 consumer resume 실패로 분류돼 같은 실패가 가려졌다.

같은 20:17:06에 944fb00c·4142658b 두 방도 동일하게 폐기됐다. 그 세션들은 다른 이유로 리포트에 안 잡혔을 뿐 같은 사건이다.

2. 시간순 인과

// 2026-08-25 20:17 — 석우주·최시원 (서버 시각, ms)
20:17:05.963  AW_64kum  ← job 배정   (1→2, 꽉참)
20:17:06.063  AW_KdQyc  ← job 배정   (0→1)
20:17:06.133  AW_CzqNH  ← job 배정   (1→2, 꽉참)
20:17:06.491  AW_KdQyc  ← job 배정   (1→2, 꽉참)   ← 623ms 만에 여유 워커 소진
20:17:06.579  석우주 AJ_UTHb5RmiJKKy → AW_64kum  worker not available
20:17:06.583                          → AW_KdQyc  worker not available
20:17:06.586                          → AW_CzqNH  worker not available
20:17:06.586  no worker available to handle job — no workers with sufficient capacity
              ↑ 실제 점유는 41/48 (빈 슬롯 7개). 그런데 서버 눈에 AVAILABLE 인 워커는
                이 3개뿐이었다 — 나머지는 2.5초 전 보고값 FULL 이 그대로 남아 후보에서 제외
20:17:06.588  최시원 AJ_ZukyvHG3Ckpb → 같은 워커 3개 → 동일하게 폐기
20:17:07.738  AW_yaQqc  ← job 배정   다른 방은 1.2초 뒤 정상 수락 — 워커는 있었다

// 클라이언트 (게스트, 세션 로그)
20:17:04.277  LiveKit session descriptor created
20:17:04.524  room connection state = connected
20:17:04.601  livekit_agent_ready_begin        ready_probe 전송, 재전송 500/1500/3500ms
              …에이전트가 방에 들어오지 않으므로 ready_response 없음…
20:17:14.612  LiveKit agent readiness wait failed (LiveKitAgentReadinessTimeoutError)
20:17:14.615  AI_SESSION | Failed to start session
20:17:17.912  UNHANDLED_REJECTION
20:17:28.557  아동: "화면/친구가 멈췄어요"

이나엘 건은 더 단순하다 — AW_tbv3g 가 20:10:16.672/.696 두 번 연속 배정으로 꽉 찬 직후 20:10:17.123 에 그 워커 하나만 후보로 잡히고, 거절당하자 곧바로 폐기됐다. 그 시점 실제 점유는 42/48(빈 슬롯 6개)이었고, 2초 뒤에는 다른 워커 3개가 정상적으로 job을 받았다.

3. 용량 모델 — 상한은 48이고, 닿은 적이 없다

워커 admission 은 CPU 기반 기본 load 함수가 아니라 PPI 자체 함수로 결정된다.

// apps/livekit-agent/agent.py:299-325
PPI_AGENT_MAX_JOBS_PER_WORKER = _parse_positive_int_env(..., 2)
PPI_AGENT_LOAD_THRESHOLD = 0.99

def _ppi_agent_load(server):
    active_jobs = len(server.active_jobs)
    return min(active_jobs / PPI_AGENT_MAX_JOBS_PER_WORKER, 1.0) * PPI_AGENT_LOAD_THRESHOLD

server = AgentServer(load_fnc=_ppi_agent_load,
                     load_threshold=PPI_AGENT_LOAD_THRESHOLD,
                     num_idle_processes=PPI_AGENT_MAX_JOBS_PER_WORKER)

워커당 2잡에서 load = 0.99 = threshold → FULL. 실측 ECS 태스크(=워커) 24개이므로 하드 실링은 24 × 2 = 48 동시 세션이다.

수요 자체도 스파이크가 아니다. 분당 신규 job 은 최대 24 / 중앙값 11이고, 하루 failed to assign job to worker 57건은 19:00~21:20 수업 피크에 고르게 퍼져 있다(20:17이 10건으로 최다). 문제는 분 단위 총량이 아니라 초 단위 동시성이다 — 1초 창 안에 3건 이상 배정된 경우가 19회 있었고, 실패는 그 창에서 발생했다.

1초 창 동시 배정 건수 분포 (19:30~20:30, n=571)
1건 : 450    2건 : 102    3건 : 15    4건 : 4

4. 서버는 왜 후보를 3개만 봤나 — 노드 단위 포화

prod LiveKit 은 노드 3대로 운영되고, agent worker 는 각자 한 노드에 등록된다. 실패한 job 을 처리한 노드에는 여유 슬롯이 0개였다 — 전체 풀에는 11개가 남아 있었는데도.

그 3개가 후보로 뽑힌 이유 — stale status

워커 24개의 슬롯 점유(서버 로그)와 status 보고(에이전트 로그)를 워커별로 교차검증했다. 21/24 일치, 불일치 3개가 정확히 서버가 시도한 그 3개다.

// 20:17:06.579 시점 교차검증 (일부)
✓ AW_yyWWGxpFtSqx  슬롯 2/2 → 예상 FULL   status로그 FULL
✓ AW_tbv3g4aLW5Ps  슬롯 2/2 → 예상 FULL   status로그 FULL
✗ AW_64kumGuumT5B  슬롯 2/2 → 예상 FULL   status로그 AVAIL   ← 20:17:05.963 에 막 참
✗ AW_KdQycxRaFqV3  슬롯 2/2 → 예상 FULL   status로그 AVAIL   ← 20:17:06.491 에 막 참
✗ AW_CzqNH6oz4ifh  슬롯 2/2 → 예상 FULL   status로그 AVAIL   ← 20:17:06.133 에 막 참
✓ AW_ov8jJiiuVrLX  슬롯 1/2 → 예상 AVAIL  status로그 AVAIL  ← 여유 있으나 다른 노드

서버 동작 — 재시도 상한은 없다

// pkg/service/agentservice.go — JobRequest
attempted := make(map[*agent.Worker]struct{})
for {                                              // 상한 없음
    selected, err := h.selectWorkerWeightedByLoad(key, attempted)
    if err != nil { "no worker available to handle job"; return }
    attempted[selected] = struct{}{}
    ...
}
// selectWorkerWeightedByLoad — 후보는 WS_AVAILABLE 인 워커만, 여유(1-load) 비례 가중 랜덤
if availableSum == 0 { return errors.New("no workers with sufficient capacity") }

워커는 접속한 노드에만 등록된다

// v1.13.2 — pkg/service/agentservice.go
:148  namespaceWorkers  map[workerKey][]*agent.Worker      // AgentHandler(=노드) 로컬 맵
:233  func (h *AgentHandler) HandleConnection(...)         // 워커가 WebSocket 으로 붙을 때
:300      h.namespaceWorkers[key] = append(workers, w)     // ← 그 노드에만 등록

// selectWorkerWeightedByLoad 는 h.namespaceWorkers 만 순회 = 자기 노드 워커만 본다

마른 노드가 job 을 가져온 이유 — affinity 도 status 기반

// v1.13.2 — 어느 노드가 이 job 을 처리할지 정하는 계산
func (h *AgentHandler) JobRequestAffinity(ctx, job) float32 {
    var affinity float32
    for _, w := range h.workers {
        if w.Status() == livekit.WorkerStatus_WS_AVAILABLE {
            affinity += max(0, h.targetLoad-w.Load())
        }
    }
    return affinity
}

근거 등급

5. 사후 점유 20.1초 — 기여하지만 원인은 아니다

아동이 방을 떠난 뒤에도 job 이 워커 슬롯을 정확히 20.1초 더 잡고 있다. 편차가 거의 없다(n=571, 중앙값 20.1s / p10 19.7 / p90 20.5) — LiveKit room departure_timeout 만료로 방이 닫힐 때까지 agent participant 가 살아 있기 때문이다. prod 로그로 확정했다(아래 6절).

// 같은 방(b47e6620) 3개 로그 소스 대조
20:16:02.295  [서버]    participant closing  user-…b47e6620  CLIENT_REQUEST_LEAVE
20:16:02      [에이전트] closing agent session due to participant disconnect
                        (RoomInputOptions.close_on_disconnect — 세션은 즉시 닫힘)
              ↓ 20초 공백 — 세션은 끝났는데 job process 는 살아 있고 슬롯을 점유
20:16:22.584  [서버]    participant closing  agent-AJ_QLqYtvKjYBkk  ROOM_CLOSED
20:16:22      [에이전트] process exiting  job_id=AJ_QLqYtvKjYBkk
20:16:22.589  [서버]    room closed

코드상 인과 — 왜 세션이 닫혀도 슬롯이 안 돌아오나

job 프로세스가 끝나는 트리거는 ipc/job_proc_lazy_main.py 에 정확히 셋뿐이다.

# livekit-agents 1.6.4 — ipc/job_proc_lazy_main.py
:240  if isinstance(msg, ShutdownRequest):        # ① 부모 워커가 종료 요청 (draining 등)
          ...self._shutdown_fut.set_result(...)

:279  @self._room.on("disconnected")              # ② 방에서 끊길 때
:280  def _on_room_disconnected(*args):
:282      self._shutdown_fut.set_result(_ShutdownInfo(reason="room disconnected"))

:289  def _on_ctx_shutdown(reason):               # ③ ctx.shutdown() 호출 시
:293      self._shutdown_fut.set_result(_ShutdownInfo(user_initiated=True, ...))

아동이 나갈 때 실제로 실행되는 코드는 이 셋 중 어느 것도 아니다 — 세션만 닫는다.

# voice/room_io/room_io.py — _on_participant_disconnected
:404  if (self._options.close_on_disconnect
          and participant.disconnect_reason in DEFAULT_CLOSE_ON_DISCONNECT_REASONS ...):
:411      logger.info("closing agent session due to participant disconnect ...")
:420      self._agent_session._close_soon(reason=CloseReason.PARTICIPANT_DISCONNECTED)
                                            ↑ 세션만 닫는다. job 은 건드리지 않는다

# voice/agent_session.py:937 _close_soon → _aclose_impl
#   → ctx.shutdown() 도, ShutdownRequest 도 호출하지 않는다

이 20초는 실제로 쓰이는 유예인가 — 실측

LiveKit 의 departure_timeout 은 "마지막 참가자가 나간 뒤 재접속할 시간을 준다"는 목적의 유예다. 그 목적이 우리 서비스에서 달성되고 있는지 19:30~20:30 전수로 확인했다.

6. 20초의 정체 — departure_timeout 확정

어디에도 "20초를 기다려라"는 코드는 없다. 20초를 만드는 주체는 LiveKit 서버이고, 에이전트 job 은 그 결과(방이 닫히는 것)를 기다릴 뿐이다.

prod 로그 — reason 필드가 직접 말해 준다

// Loki {service_name="ppi-livekit", env="prod"} |= "closing idle room"  (20:14~20:18, 72건)
20:14:01.590  caller=rtc/room.go:804  msg="closing idle room"  reason="departure timeout"
20:14:08.677  caller=rtc/room.go:804  msg="closing idle room"  reason="departure timeout"
...
20:17:36.587  reason="departure timeout"  room=ppi-7f7291c4-…-taeyang2_room-0eecea6f   ← 석우주의 실패한 방
20:17:38.587  reason="departure timeout"  room=ppi-98a60cf9-…-newpp06_woosung-746cbe6c  ← 최시원의 실패한 방

reason="empty timeout" 은 0건

서버 코드 — 두 타이머가 갈리는 지점

// github.com/livekit/livekit — pkg/rtc/room.go, CloseIfEmpty()
if r.FirstJoinedAt() > 0 && r.LastLeftAt() > 0 {
    elapsed = time.Now().Unix() - r.LastLeftAt()
    timeout = r.protoRoom.DepartureTimeout       // 누군가 들어왔다가 다 나간 방 ← 우리 케이스
    reason  = "departure timeout"
} else {
    elapsed = time.Now().Unix() - r.protoRoom.CreationTime
    timeout = r.protoRoom.EmptyTimeout            // 아무도 들어온 적 없는 방
    reason  = "empty timeout"
}
if elapsed >= int64(timeout) {
    r.Close(types.ParticipantCloseReasonRoomClosed)
    r.logger.Infow("closing idle room", "reason", reason)
}

// pkg/config/config.go — 기본값
:550    EmptyTimeout:     5 * 60,   // 300초
:551    DepartureTimeout:     20,   // ← 실측 20.1초와 일치

7. 조사 레시피와 함정

데이터 소스

함정

확진 절차

1. 세션 로그에서 LiveKit session descriptor created 의 roomName 을 얻는다 (UUID 접미사가 AI 스텝마다 다르다 — 세션 roomId 로 검색하면 수십 개가 섞인다)
2. 그 접미사 8자로 Loki prod 를 조회해 assigned job to worker 가 있는지 본다 — 없고 no worker available to handle job 이 있으면 이 사건이다
3. 같은 초의 전체 assigned job to worker 타임라인을 뽑아 거절한 워커들이 직전 1초 내에 채워졌는지 확인한다 → 버스트 경합 확정
4. 같은 시각 풀 전체 점유를 재구성해 빈 슬롯이 남아 있었는지 본다 → 용량 부족과 구별

8. 클라이언트 쪽 동작과 재시도

에이전트가 들어오지 않으면 클라이언트는 10초를 기다린 뒤 세션 시작을 포기했다. 실패했다는 통보조차 받지 못한다 — 서버는 job 을 폐기하고 아무것도 알려주지 않는다.

• apps/web/lib/voice-agent/livekit-client-session.ts:49 — LIVEKIT_AGENT_READY_TIMEOUT_MS = 10000
• :306 createLiveKitAgentReadinessGate — 타임아웃 시 LiveKitAgentReadinessTimeoutError
• :1714~1727 — ready_probe 를 500 / 1500 / 3500ms 에 재전송. 받을 상대가 없으므로 무의미하다
• :1819 — logger.error("LiveKit agent readiness wait failed") 후 throw → AI_SESSION | Failed to start session
• 핸드셰이크 프로토콜: apps/web/lib/voice-agent/livekit-readiness-handshake.ts (ppi.ready_probe → ppi.ready_response → ppi.ready_ack, topic ppi-agent-control)

재시도 추가 로컬 적용

원인이 노드 포화든 stale status 든 재시도는 원인과 무관하게 동작한다. 실측상 실패 1.2초 뒤에는 다른 방이 정상 수락됐다.

// apps/web/lib/voice-agent/livekit-readiness-retry.ts (신설, 순수 함수)
READINESS_RETRY_MAX_ATTEMPTS = 1
READINESS_RETRY_DELAY_MS     = 800

shouldRetryAgentReadiness(error, attemptsMade)
  ① error.name === "LiveKitAgentReadinessTimeoutError"
  ② attemptsMade < MAX      // getUserMedia·네트워크 등 다른 실패는 재시도 안 함

// apps/web/entities/guest-session/model/use-ai-session.ts:4658 handleStartSession
startSession() 실패
  → readiness_retry_scheduled  {attempt, elapsedMs, reason}
  → 800ms 대기
  → generation 변경 확인 // 스텝이 넘어갔으면 readiness_retry_abandoned 후 중단
  → startSession() 재호출
       createVoiceSessionId() 가 새 UUID → 새 방 → 노드·워커 재선택
  → 성공 readiness_retry_succeeded / 최종 실패 readiness_retry_exhausted

9. 개선 방향

원인이 노드 단위 포화로 좁혀지면서 우선순위가 바뀌었다. 각 노드의 여유 워커를 늘리는 조치가 유효하고, 클라이언트 재시도가 유일한 확실한 안전망이다.

dev 서버 검증 항목 (PR #1027)

관련 문서