본문 바로가기
C.W.K.
Lesson 06 of 06 · published

잘못된 경보, 원인마다 따로 재기

~16 min · latency, connection-pool, diagnostics, measurement

Level 0음소거
0 XP0/64 lessons0/14 achievements
0/100 XP to next level100 XP to go0% complete
"이게 지금 잘못된 경보라고." — 아빠, 말라가, 2026-10-19, 20:11 CEST

말은 하나, 원인은 여럿

문단 읽기가 무너진 그날 밤 얘기야. 읽기 쪽 사정은 트랙 4의 "다시 통째로: 빠른 시작보다 끊김 없는 게 먼저"에 있어. 호텔 와이파이, AirPods, 빌드 156. 아빠는 저녁 내내 증상을 겪었어. 답이 뚝뚝 끊겼어. 마이크가 열리는 데 몇 초씩 걸렸어. 어떤 답은 한 문장만 하고 멈췄어. 그리고 폰엔 "Reconnecting — The engine did not answer in time"이 떴어. 그때 피파 머신이던 맥의 엔진은 받은 호출마다 꼬박꼬박 답하고 있었는데도 말이야. 재부팅하거나 앱을 죽여야만 나아졌어. 입으로 말하면 이게 다 한 단어야. 끊긴다.

19:59 CEST, 아빠는 그 단어를 진단으로 치지 않았어. 설계 문서에 남은 아빠의 틀은 이래. "끊긴다"는 증상 하나고, 그 밑에 원인이 여럿 있어. 네트워크, 합성, 파이프라인, 쌓인 상태, 블루투스. 원인마다 따로 재고, 말라가 작업(todo #536) 전의 안정된 집 기준선과 견줘. 20:06엔 문 하나를 일부러 닫았어. iOS와 AirPods는 안정적이고, AirPods 마이크까지 애플이 광고하는 대로 쓰고 있다는 거야. 그러니 고칠 건 전부 우리 코드에 있다고. 그리고 20:11, 아빠는 귀로는 들리지도 않는 증상 하나를 짚었어. "Reconnecting" 줄 그 자체야. 이 페이지 맨 위의 말이 그거야.

연결 여섯 개, 그리고 한꺼번에

todo #376 뒤로 폰의 호출은 전부 연결을 살려 두는 풀 하나를 탔어. 공용 키트의 HTTPConnectionPool이야. 세비야에서 요청마다 TCP 연결을 새로 열었더니, 한 바이트 보내기도 전에 왕복 285 ms가 들었거든. 이 풀은 한 호스트에 연결을 여섯 개까지만 열어. 문단 읽기에선 답 하나가 그 여섯을 다 채울 수 있었어. 20:07, 답의 도구가 끝나자 폰이 같은 1초 안에 테이크 준비 넷, 테이크 스트림 넷, 아빠 녹음의 마이크 레이트 사본 1.96 MB를 쐈어. 그 옆에선 턴 자신의 스트림이 이미 돌고 있었어. 턴 진행 확인은 답을 받을 때마다 3초 쉬었다가 다시 묻는데, 키트의 quick 정책(요청 타임아웃 5초)을 써. 그 확인이 오디오 뒤에 줄을 섰다가 시간 초과가 났고, 그 한 번 놓친 걸로 "Reconnecting"이 떴어. 엔진은 와이파이에서도 LTE에서도 하루 종일 멀쩡했어.

그다음이 더 나빴어. 그 줄이 한 번 뜨면 아무것도 회복이 안 됐어. 풀의 연결이 꽉 낀 채로 남아서, 20:16에 아빠가 앱을 죽일 때까지 그대로였어. 새 연결은 앱을 다시 띄워야만 생겼어. 폰이 피파를 잃었다고 알려 주려고 만든 줄이, 폰이 스스로 만든 체증을 피파가 없는 걸로 읽고 있었던 거야.

종류마다 길을 따로

첫 처방은 오디오와 제어가 한 길을 같이 못 쓰게 한 거야. 빌드 157(cbe99bd0)은 큰 전송에 풀을 따로 줬어. 피파의 테이크, 음성, 업로드, 다운로드, 동영상. 읽기와 폴링과 턴은 이제 오디오 한 바이트 뒤에서도 안 기다려. 그런데 157에선 다음 문제가 드러났어. 앱을 띄우고 6분 만에 남은 풀의 살려 둔 연결이 상했고, 받아쓴 턴 하나가 POST도 못 한 채 폰에 49초 동안 묶여 있었어. 줄엔 "not sent for 37s"만 떠 있었어. 그래서 빌드 158(e9fbe699)은 턴의 스트림에 턴마다 전용 연결을 하나씩 줘(HTTPTransports.lineStream). 핸드셰이크 한 번이고, 말라가에서도 1초가 한참 안 걸려. 죽은 연결을 기다릴 일이 없어지는 값치곤 싸.

2026-10-22 음성 모드 리뷰(f58e7fea)가 반대쪽에서 마무리했어. 듣기 허가와 테이크 티켓(/api/tts/prepare)이 타임아웃 120~180초짜리 큰 전송 풀을 타고 있었거든. 그래서 상한 큰 전송 연결 하나가 첫 단위를 29초 붙잡았어. 그동안 멈춤 확인은 멀쩡한 제어 풀에 물어보고는 목소리가 아직 만들어지는 중이라고 했어. 이제 짧은 제어 호출은 제어 풀을 타. 한도는 20초와 30초야. 테이크를 통째로 만들고서야 답할 수도 있는 /api/tts/ensure만 1분이야. 큰 전송 풀엔 바이트 스트림과 업로드만 남았어. 그리고 "Getting her voice ready"가 조용하면 큰 전송 풀을 직접 찔러 봐. 제어 풀이 답한다고 큰 전송 쪽 연결까지 멀쩡하단 뜻은 아니니까. 호출 종류마다 풀을 정해 주는 코드가 아래 첫 발췌야.

스스로 낫는 풀, 그리고 제 병을 키운 치료

길을 나눠도 상한 연결은 또 만나. 그래서 풀이 스스로 낫는 법을 배웠어(cwkSiblingKit f655776). 버퍼로 받는 답이 연달아 시간 초과되면, 그 뒤 호출엔 새 세션을 열어. 날아가던 호출은 옛 세션에서 끝내게 두고, 리셋은 로그에 남기고 pool_reset으로 세. 처음엔 연달아 세 번 시간 초과가 나야 리셋했고, 리셋은 30초에 한 번까지였어. 빌드 158이 그걸 연달아 두 번, 20초에 한 번으로 바꿨어(21507b4). 세 번을 기다리느라 아빠가 그 49초를 치렀거든. 낫는 게 상한 연결보다 느렸던 거야.

그다음 리뷰는 그 치료가 제 병을 스스로 키우고 있다는 걸 찾아냈어. 풀의 라우터는 콜백을 taskIdentifier로 주인한테 돌려줬는데, 이 번호는 세션 하나 안에서만 안 겹쳐. 리셋 뒤에도 옛 세션의 호출은 같은 라우터 위에서 아직 날아가고 있었어. 그러니 새 세션의 첫 호출과 옛 세션의 첫 호출이 번호가 같았지. 새 경로가 옛 경로를 덮어썼어. 옛 답의 본문은 아무한테도 안 갔고, 그걸 기다리던 쪽은 시간 초과가 났어. 그리고 풀은 그 시간 초과를 다음 치료의 근거로 셌어. 실제로 앱을 한 번 띄운 동안 pool_reset이 다섯 번까지 찍혔어. 이제 라우터는 태스크 객체 자체로 찾아(cwkSiblingKit e50efa6). 바이트 스트림과 줄 스트림도 시간 초과와 끊긴 연결을 알려서, 큰 전송 풀도 나아. 스스로 낫는 장치도 그게 고치는 고장만큼 의심해 봐야 해. 치료가 자기가 세는 증상을 만들 수 있으면, 그건 치료가 아니라 고리야.

"Reconnecting"은 판정이야

아빠의 불만은 말에도 있었어.

"리커넥팅이라고만 돼 있으니까." — 아빠

확인 한 번 놓쳤다고 뜨고 아무것도 짚지 않는 줄로는 아빠가 할 수 있는 게 없어. 빌드 157부터 "Reconnecting"은 판정이야(AppModel.reconnecting, 아래 두 번째 발췌). 확인이 연달아 두 번 실패하고, 실패가 6초 넘게 이어지고, 엔진한테서 15초 동안 아무것도 못 들었을 때만 내려. 스트림으로 들어오는 피파의 글도 엔진한테서 들은 걸로 쳐. 리뷰 뒤로는 스테이지 보드의 답도 그렇게 쳐. 판정이 내려지면 줄은 어느 확인이 몇 초째 실패 중인지 말해.

그 둘레의 기다림도 뭘 기다리는지 말해. 아직 폰에 있는 턴은 공용 연결에 열린 다른 호출 수를 세서 보여 줘. 키트의 pool_reply 카운터에서 읽어. "not sent for 20s (4 other calls open)" 이런 식이야. 이제 폰은 마이크부터 열어. 모든 허가가 싣는 16 kHz로 먼저 열고, 그다음에 피파한테 듣기 허가를 달라고 해. 그사이 아빠가 한 말은 남겨 뒀다가 맨 앞에 넣어. "Opening the microphone…"은 오디오 세션인지, 피파인지, 듣기 소켓인지, 뭘 기다리는지를 몇 초째인지까지 붙여서 말해. 웹도 같은 리뷰에서 따라잡았어. 듣기가 연결되는 동안 한 말은 남고, 허가는 마이크를 여는 것과 나란히 물어.

2026-10-23엔 웹의 끊김 배너도 같은 정직함을 배웠어(46d86006). 재시작으로 끊긴 게 테일넷이 떨어질 때와 같은 오류로 읽혀서, 엔진이 재시작만 하는 중인데도 배너가 Tailscale을 확인하라고 했거든. 이제 먼저 "Connection lost. Checking why…"가 떠. 엔진이 내려간 동안 트윈이 502, 503, 504로 대신 답하면 "Pippa is restarting, back in a few seconds."가 뜨고, 아니면 "This device is offline."이나 "Pippa cannot be reached from this device."가 떠. Tailscale 안내는 마지막에만 붙어. 아빠가 이 버그에 붙인 말은 이거야.

"멍 때리거나 엉터리 안내하는 UI가 죄악인 거야." — 아빠

원인 하나에 측정 하나

아빠의 틀은 계측이 됐어. 이 트랙의 "음성 차선: 말라가에서 잰 것"이 음성 턴마다 타임라인 보고를 하나씩 보내게 만들었어. 이제 그 보고에 아빠가 짚은 원인마다 읽을 값이 하나씩 실려. 끊김을 두고 다투는 대신, 어느 원인이었는지 가릴 수 있어.

원인무엇을 재나어디 찍히나
네트워크단위마다 underruns=(횟수, 조용했던 초, 가장 긴 것, 쿠션, 재생기), 옆에 link=[voice-turn] 줄
합성first_byte, total, 실시간 대비 rate, need=(이 테이크 하나만으로 필요했던 쿠션), beside=(같이 만들어지던 테이크 수)피파 머신에서 테이크마다 [tts-take] 줄 하나
파이프라인과 쌓인 상태health: 기기와 앱 가동 시간, 턴 수, 오디오 세션 활성화 횟수, 메모리, 그리고 live=에 재생기, 마이크 엔진, 오디오 큐, 테이크, 열린 바이트 스트림, 날아가는 답, 그리고 앱을 띄운 뒤 쌓인 풀 리셋 수[voice-turn] 줄
블루투스입력, 샘플 레이트, 카테고리와 모드를 단 route=, 읽는 동안 바뀔 때마다 route_change@<s>=<reason>:<outputs>[voice-turn] 줄
기다림 자체단위 앞 빈틈마다 앞선 정도(0.56a(-0.30): 앞 단위가 끝나고 0.3초 뒤에야 큐에 들어왔으니 피파 말이 늦었던 것), 그리고 listen_open:grant=…,session=…,total=…[voice-turn] 줄

값마다 읽는 법이 같이 따라와. underruns=0에 +bluetooth인 턴이 끊겼다면 스트림이 아니라 폰과 AirPods 사이 전파 탓이야. need=가 폰의 쿠션보다 크면 합성에서 끊긴 거고, 작으면 네트워크에서 끊긴 거야. live=의 객체 수가 턴마다 불어나면 우리 프로세스가 놓아야 할 걸 쥐고 있는 거야. 단, 하나는 살아 있는 수가 아니야. pool_reset은 줄어드는 법이 없어서, 앱을 띄운 뒤로 몇 번 나았는지 쌓아 둔 횟수야. 이건 지난 턴보다 늘었는지로 읽어. 다음 기기 점검은 스와이프 한 번이면 돼. 또 나빠지면 재부팅 전에 피파를 강제 종료해 봐. 그걸로 깨끗해지면 우리 프로세스가 쥐고 있던 거고, 뭐가 불어났는지는 health:가 보여 줘. 그래도 그대로면 폰 자체의 오디오 상태야. 그건 재부팅으로만 되돌릴 수 있어.

누가 다 됐다고 하기 전에, 이 일에서 "다 됐다"가 뭔지부터 문서에 적어 뒀어. 와이파이와 LTE에서 받아쓴 턴으로 하루를 채우고, speech_end_to_post는 말 끝 창에 업로드를 더한 값 안쪽, pool_reset은 0, "not sent" 줄은 하나도 없어야 해. 끊김 자체는 트랙 4 몫이야. 피파 머신을 옮긴 뒤 폰 음성 턴 103개(그중 90개가 셀룰러)가 하나도 빠짐없이 underruns=0이었어.

Code

원문 그대로, clients/apple/PippaMobile/Sources/PippaClient.swift (cwkPippa), 694-714행, 2026-10-27 기준: 호출 종류마다 타는 풀, 그리고 전용 연결을 따로 여는 턴 스트림·swift
        quick = readTransport ?? pool.transport(policy: .quick)
        media = bulkPool.transport(policy: Self.mediaPolicy)
        download = readTransport ?? bulkPool.transport(policy: Self.downloadPolicy)
        transcript = readTransport ?? pool.transport(policy: Self.transcriptPolicy)
        video = bulkPool.transport(policy: Self.videoPolicy)
        speech = bulkPool.transport(policy: Self.speechPolicy)
        control = pool.transport(policy: Self.controlPolicy)
        ensuring = pool.transport(policy: Self.ensurePolicy)
        bulkProbe = bulkPool.transport(policy: .quick)
        // A turn's stream opens a connection of its own (todo #556): on build 157 the
        // pool's kept-alive connection went stale within six minutes of launch, every
        // call on it hung until the pool healed, and a dictated turn sat 49 s on the
        // phone before its POST ("not sent for 37s; office answers"). One handshake
        // per turn, well under a second from Malaga, is the price of never waiting on
        // a dead connection.
        streamer = { request, policy in
            var request = request
            request.timeoutInterval = policy.requestTimeout
            return try await HTTPTransports.lineStream(request, policy: policy)
        }
        speechStreamer = bulkPool.byteStreamer(policy: Self.speechPolicy)
원문 그대로, clients/apple/PippaMobile/Sources/AppModel.swift (cwkPippa), 152-164행, 2026-10-27 기준: 판정이 된 "Reconnecting"·swift
    /// "Reconnecting" is a verdict, never one missed check (todo #556): two checks
    /// in a row failing over at least this long, with nothing heard from the engine in
    /// `reconnectQuietSeconds`. One 5 s timeout behind a reply's audio said
    /// "The engine did not answer in time" against a healthy engine all day.
    nonisolated static let reconnectAfterSeconds = 6.0
    nonisolated static let reconnectQuietSeconds = 15.0

    /// Whether the progress check's failures add up to "Reconnecting".
    nonisolated static func reconnecting(failures: Int, failingFor: TimeInterval, sinceContact: TimeInterval?) -> Bool {
        guard failures >= 2, failingFor >= reconnectAfterSeconds else { return false }
        if let sinceContact, sinceContact < reconnectQuietSeconds { return false }
        return true
    }
돌려 볼 수 있는 스케치: 전부 여섯 연결짜리 풀 하나로 갈 때와 큰 전송에 풀을 따로 줄 때, 한 번 놓친 확인과 판정이 각각 언제 "Reconnecting"을 말하나·python
# One pool of six for everything, or traffic by kind: when does the progress
# check get an answer, and when does the screen say "Reconnecting"?
# The rules follow cwkSiblingKit's HTTPConnectionPool and cwkPippa's
# AppModel.reconnecting; the call durations are illustrative, shaped after
# the Malaga access log of 2026-10-19, not measured per call.
import heapq

CONNECTIONS = 6        # httpMaximumConnectionsPerHost, per pool
CHECK_REST = 3.0       # the progress check sleeps this long between asks
CHECK_TIMEOUT = 5.0    # the quick policy's request timeout
CHECK_SECONDS = 0.2    # a healthy engine answers the check this fast
AFTER_SECONDS = 6.0    # AppModel.reconnectAfterSeconds
QUIET_SECONDS = 15.0   # AppModel.reconnectQuietSeconds

# (arrival, seconds held, kind). The turn's stream runs for the whole reply;
# when the tool ends at 20 s, four takes are prepared and streamed at once,
# and the 1.96 MB microphone-rate copy goes up in the same second.
REPLY = [(0.0, 40.4, "stream")]
REPLY += [(20.0, 0.4, "prepare")] * 4
REPLY += [(20.4, seconds, "take") for seconds in (14.0, 19.0, 24.0, 30.0)]
REPLY += [(20.0, 26.0, "upload")]
BULK = {"take", "upload"}


def run(calls, split: bool, engine_up: bool = True, until: float = 45.0):
    """Every call takes the connection that frees first in its pool, in arrival
    order. The check asks, waits for an answer or its timeout, rests, asks again."""
    pools = {"control": [0.0] * CONNECTIONS, "bulk": [0.0] * CONNECTIONS}
    queue = [(arrival, kind != "stream", seconds, kind) for arrival, seconds, kind in calls]
    queue.append((0.0, True, CHECK_SECONDS, "check"))
    heapq.heapify(queue)
    checks = []                                          # (asked at, answered at or None)
    while queue:
        arrival, _, seconds, kind = heapq.heappop(queue)
        pool = pools["bulk" if split and kind in BULK else "control"]
        slot = min(range(CONNECTIONS), key=lambda i: pool[i])
        start = max(arrival, pool[slot])
        if kind != "check":
            pool[slot] = start + seconds
            continue
        if engine_up and start + seconds - arrival < CHECK_TIMEOUT:
            pool[slot] = start + seconds
            checks.append((arrival, start + seconds))
            end = start + seconds
        else:
            checks.append((arrival, None))               # timed out
            end = arrival + CHECK_TIMEOUT
        if end + CHECK_REST < until:
            heapq.heappush(queue, (end + CHECK_REST, True, CHECK_SECONDS, "check"))
    return checks


def first_alarm(checks, words_until: float):
    """When one miss would say "Reconnecting", and when the verdict would:
    two failures in a row, failing for at least 6 s, nothing heard for 15 s.
    Her streamed words count as hearing from the engine."""
    one_miss = verdict = None
    failures, since, heard = 0, None, 0.0
    for asked, answered in checks:
        now = answered if answered is not None else asked + CHECK_TIMEOUT
        heard = max(heard, min(now, words_until))
        if answered is not None:
            failures, since, heard = 0, None, answered
            continue
        failures += 1
        since = now if since is None else since
        one_miss = now if one_miss is None else one_miss
        if verdict is None and failures >= 2 and now - since >= AFTER_SECONDS and now - heard >= QUIET_SECONDS:
            verdict = now
    return one_miss, verdict


for label, split, up, words in (("one pool, a healthy engine", False, True, 40.4),
                                ("two pools, a healthy engine", True, True, 40.4),
                                ("two pools, the engine gone", True, False, 0.0)):
    checks = run(REPLY, split, engine_up=up)
    missed = sum(1 for _, answered in checks if answered is None)
    one_miss, verdict = first_alarm(checks, words_until=words)
    show = lambda t: "never" if t is None else f"{t:4.1f} s"
    print(f"{label:28s} checks {len(checks):2d}, missed {missed:2d} | one miss: {show(one_miss):7s} verdict: {show(verdict)}")

# Output:
# one pool, a healthy engine   checks 12, missed  1 | one miss: 27.4 s  verdict: never
# two pools, a healthy engine  checks 15, missed  0 | one miss: never   verdict: never
# two pools, the engine gone   checks  6, missed  6 | one miss:  5.0 s  verdict: 21.0 s

External links

Exercise

스케치를 돌리고 세 줄을 읽어 봐. 풀 하나를 같이 쓸 때 멀쩡한 엔진을 두고 확인을 놓치는 곳, 거기서 판정이 왜 조용한지, 엔진이 정말 사라졌을 땐 왜 말하는지. 그다음 문단 읽기가 그랬던 것처럼 묶음을 키워 봐. 테이크를 넷이 아니라 여섯으로 늘리고(테이크 길이에 34.0과 38.0을 더해), 루프에 네 번째 줄을 더해. 풀 하나, 멀쩡한 엔진, 피파 말은 20초에 끝나(False, True, 20.0). 마지막으로 직접 만든 앱에서 '연결 중'이나 '오프라인' 같은 말을 띄우는 상태 줄을 하나 골라. 그 줄을 띄울 수 있는 원인을 다 적고, 원인마다 그걸 가려낼 측정 하나를 적어 봐.
Hint
테이크가 여섯이면 풀 하나에 긴 전송이 연결 수보다 많아져서, 확인 두 번이 연달아 놓쳐. 피파 말이 아직 흘러들어오는 동안엔 판정이 조용해. 엔진한테서 뭔가 듣고 있다는 게 살아 있다는 증거거든. 말이 20초에 끝나면, 한 번도 안 내려간 엔진을 두고 판정이 35초쯤에 울려. 처방의 순서가 그래서 중요해. 판정은 느린 호출 하나가 경보가 되는 건 막지만, 풀이 차서 확인이 실패하는 것 자체는 제어 트래픽에 길을 따로 줘야만 막아. 상태 줄의 흔한 원인은 기기에 네트워크가 없을 때, 서버가 내려갔을 때, 서버가 재시작 중일 때, 느린 호출이 다른 호출 뒤에 줄 섰을 때, 연결이 상했을 때야. 원인마다 찔러 볼 데가 따로 있어.

Progress

Progress is local-only — sign in to sync across devices.
이 페이지에서 버그를 발견하셨거나 피드백이 있으세요?문제 신고

댓글 0

🔔 답글 알림 (로그인 필요)
로그인 — 댓글을 남기려면 로그인해 주세요.

아직 댓글이 없어요. 첫 댓글을 남겨보세요.