도착하지 않은 완료 이벤트: 두 번의 조용한 드롭

한 사용자가 다운로드 버튼 하나가 완료되지 않는다고 보고했습니다. 스피너가 계속해서 돌아갔습니다. 가장 확실한 추측은 렌더링이 실패했다는 것이었고, 그래서 저는 오류를 찾아 나섰습니다. 오류는 없었습니다. 파일은 객체 스토리지에 존재했고, 데이터베이스 행은 그 파일을 가리키고 있었으며, 동일한 입력을 로컬에서 재현했을 때 바이트 단위까지 동일한 결과물이 생성되었습니다. 작업은 세 번이나 성공했습니다. 오직 알림만 유실되었는데, 그마저도 서로 다른 두 가지 방식으로 유실되었습니다.

로그의 실제 내용

파이프라인은 평범했습니다. 클라이언트가 작업을 게시하면, 서버는 202를 반환하고 백그라운드에서 렌더링한 다음, pub/sub 채널에 완료 이벤트를 게시합니다. 서버-전송 이벤트(server-sent events) 엔드포인트가 구독 중인 모든 브라우저 탭으로 해당 이벤트를 전파합니다.

저는 게시 타임스탬프를 SSE 연결 시간대에 맞춰 정렬했습니다. 각 연결은 종료(close) 시에 지속 시간을 기록하므로, 시작 시간은 종료 시간에서 지속 시간을 뺀 값입니다.

SSE window (server log)   completion published   received
13:36:04 - 13:36:33   ->  13:36:44               no subscriber
13:37:14 - 13:41:25   ->  13:41:32               no subscriber
13:45:59 - 13:49:41   ->  13:50:07               no subscriber

세 번 중 세 번 모두, 이벤트는 비어 있는 채널로 전송되었습니다. Redis pub/sub은 부재중인 구독자를 위해 큐에 메시지를 저장하지 않으므로, 메시지는 게시되는 순간 사라졌습니다. 거기까지는 한 시간 안에 명확해졌습니다. 더 오래 걸린 것은 두 개의 서로 다른 버그가 동일한 증상을 일으키고 있다는 사실을 받아들이는 것이었습니다.

동일한 로그에 있는 또 다른 세부 정보가 누락 자체보다 더 중요한 것으로 밝혀졌습니다. 바로 연결 지속 시간이 매우 불규칙했다는 점입니다. 2.58초, 28.59초, 5.79초, 35.2초. 20초 하트비트와 30분 세션 제한이 있는 장기 실행 스트림이 2.58초 후에 닫혀서는 안 됩니다.

한 가지 실수: 항목별 완료 신호가 전체 스트림을 닫아버림

이 시스템의 상태 코드는 마지막 세 자리가 단계를 인코딩하는 정수입니다. 헬퍼는 상태가 터미널인지 여부를 결정했습니다.

func isDone(s Status) bool {
	r := s % 1000
	return r == 500 || r == 600 || r == 800
}

SSE 루프는 해당 헬퍼를 사용하여 스트리밍을 중지하고 반환할 시점을 결정했습니다. 얼마 전 "하나의 트랙 렌더링 완료"에 대한 새로운 상태가 추가되었고, 번호는 5600이었습니다. 아무도 5600 % 1000이 600이라는 사실을 알아차리지 못했습니다.

그래서 모든 성공적인 항목별 완료는 터미널로 분류되었고 핸들러는 반환되었습니다. 스트림이 닫혔습니다. 한 테스트가 그 비대칭성을 극명하게 보여주었습니다.

status=5600 (item done)     isDone=true   terminal=true    stream closes
status=5910 (item failed)   isDone=false  terminal=false   stream stays

실패는 연결을 유지했지만 성공은 연결을 끊었습니다. 사용자가 아홉 개의 항목을 대기열에 넣으면 첫 번째 성공 시 스트림이 닫혔고, 브라우저는 1초의 재연결 지연 시간 동안 대기했으며, 그 시간 창 안에 게시된 모든 완료 알림은 사라졌습니다. 불규칙한 연결 지속 시간의 원인이 바로 이 버그였는데, 프로덕션 환경에서 몇 주 동안 발견되었지만 불안정한 네트워킹 문제처럼 보일 뿐이었습니다.

해결책은 간단하며, 중요한 것은 후반부입니다:

func isSSETerminal(s Status) bool {
	if s == StatusItemDone {
		return false
	}
	return (isDone(s) && s >= StatusFirstPhaseDone) ||
		s == StatusError || s == StatusFailed
}

다른 호출자들이 isDone에 의존하기 때문에 그대로 두었고, 0부터 10000까지의 모든 정수를 순회하며 그 한 값을 제외하고는 새로운 조건자가 기존 표현식과 일치함을 단언하는 테스트를 작성했습니다. 그 결정을 이름 있는 함수로 추출했기에 비로소 그 테스트가 가능했습니다. 원래 코드는 HTTP 응답 작성기, 데이터베이스 읽기, 속도 제한기까지 소유한 230줄짜리 핸들러 안에 있는 인라인 불리언이었습니다.

일반적인 교훈은 잘못된 상수 하나에 대한 것이 아닙니다. 식별자에 대한 산술 연산으로부터 제어 흐름을 파생시키는 것은, 모든 새로운 식별자가 멀리 떨어진 곳의 동작을 소리 없이 변경할 기회가 됨을 의미합니다. 상태 정의에 terminal bool 필드가 있었다면 애초에 그런 실수를 할 수 없었을 것입니다.

두 번째 누락: 작업을 시작한 후 구독하기

두 번째 누락은 클라이언트에 있었습니다. 순서는 작업을 게시하고, 202 응답을 기다린 다음, SSE 연결을 열고 관심사를 등록하는 것이었습니다.

렌더링에 시간이 걸릴 때는 이 방식이 작동합니다. 작업이 빠를 때는 실패합니다. 이 배치에 있던 한 항목은 단일 세그먼트를 가지고 있었고, 그 렌더링은 브라우저가 구독을 등록하기도 훨씬 전인 1.5초 만에 끝났습니다. 해당 항목은 매번 실패했지만, 30개나 200개의 세그먼트를 가진 항목들은 거의 항상 작동했습니다. 이 버그는 데이터에 따라 달라지는 것처럼 보였고, 이것이 오랫동안 살아남은 이유입니다. 아무도 특별하다고 생각하지 않았던 단 하나의 입력에서만 재현되었기 때문입니다.

명백한 해결책은 먼저 구독하는 것입니다. 제가 그렇게 했지만, 순서만으로는 충분하지 않았는데, 그 이유는 구현 중에 문제가 되었기 때문에 언급할 가치가 있습니다. 클라이언트는 pending set이 비워지자마자 연결을 닫았고, 이 확인은 모든 메시지에 대해 실행되었습니다. 서버는 연결이 열리는 순간 초기 상태 프레임을 보냅니다. 따라서 연결을 일찍 여는 것만으로는 연결, 초기 프레임 수신, pending set 비어 있음, 연결 종료라는 결과가 발생했습니다. 경쟁 상태가 바로 다시 발생했습니다. 일찍 구독하고 구독을 유지하는 것은 두 가지가 아닌 하나의 변경 사항입니다.

명백한 폴백이 오히려 상황을 악화시킨 이유

완료 이벤트를 놓칠 수 있기 때문에 본능적으로 복구 경로를 추가하게 됩니다. 저는 두 번이나 복구 경로를 설계했지만 둘 다 폐기했습니다.

첫 번째는 클라이언트 폴링이었습니다. 게시 후 응답이 나타날 때까지 몇 초마다 결과 엔드포인트를 폴링하는 것입니다. 폴 타이머와 작업 ID가 어디에 있는지 알기 전까지는 견고해 보입니다. 그것들은 브라우저 메모리에 있습니다. 최초 버그 보고서에는 "여러 번 새로고침한 후에도" 항목이 다운로드되지 않는다고 되어 있었습니다. 새로고침은 폴백이 의존하는 바로 그 상태를 파괴합니다. 이 폴백은 보고된 경우를 제외한 모든 경우를 처리했습니다.

두 번째는 서버 측 재실행이었습니다. 각 결과를 작업별로 키가 지정된 해시에 저장하고, 클라이언트가 연결되면 해시를 읽어 발견된 모든 결과를 재실행하는 것입니다. 원칙적으로는 새로고침에도 문제가 없습니다. 실제로는 해결하려던 문제보다 더 심각한 장애를 일으켰습니다. 이제 클라이언트가 게시하기 전에 구독하므로, 연결 시점에 항목은 항상 보류 집합에 있습니다. 이전 실행의 오래된 결과가 재실행되어 해당 보류 중인 항목과 일치하게 되고, 아직 전송되지도 않은 요청에 대한 응답으로 처리될 것입니다. 사용자는 조용히 이전 아티팩트를 받고 그것이 새것이라고 믿게 될 것입니다. 끝없이 돌아가는 스피너는 사용자가 볼 수 있는 나쁜 결과입니다. 올바르게 보이는 잘못된 파일은 더 나쁩니다.

세 번째 문제가 있었습니다. SSE 핸들러가 다른 소비자들과 공유되었는데, 그중 하나가 failed로 끝나는 모든 상태를 자신의 실패로 분류했습니다. 저장된 항목별 실패를 재실행하면 관련 없는 작업에서 오류 배너가 표시되었을 것입니다.

그래서 폴백은 완전히 폐기되었고, 애초에 이벤트를 잃지 않는 데 노력을 기울였습니다. 작업을 시작하기 전에 구독하고, 패널이 열려 있는 동안 구독을 유지하며, 항목별 완료 시 스트림을 닫지 않도록 했습니다. 주 경로보다 약한 복구 경로는 이중화가 아닙니다. 그것은 동일한 조건에서 실패하는 두 번째 유지 관리 대상일 뿐이며, 새로운 종류의 버그를 추가할 뿐입니다.

여전히 보장되지 않는 부분

폴백을 제거한다는 것은 더 작은 보장을 수용한다는 의미이며, 그렇지 않은 척하기보다는 그 점을 명시하는 것이 가치 있습니다. 이는 영속적인 완료가 아닌 실시간 전달 신뢰성입니다. 만약 렌더링 도중 서버가 재시작되거나, pub/sub 링크가 잠시 끊기거나, 브라우저가 백그라운드 탭에서 프레임을 놓칠 만큼 오랫동안 멈추면, 알림은 여전히 사라집니다.

폴백을 대체한 것은 클라이언트 측 타임아웃입니다. 30분 후 해당 아이템은 오류 상태로 전환되고 사용자는 재시도할 수 있습니다. 이는 자동 복구보다 더 나쁜 경험이지만, 시스템이 실제로 약속하는 바에 대해 솔직하게 말해줍니다. 이 모든 것을 시작하게 한 단일 세그먼트 아이템의 경우, 재시도에는 1.5초가 걸립니다.

동일한 검토 과정에서 두 가지 작은 조정 사항이 나왔습니다. 스트림의 세션 상한은 클라이언트 타임아웃을 초과해야 했습니다. 그렇지 않으면 서버가 먼저 연결을 끊고 이벤트를 누락시키는 바로 그 재연결 간격을 만들어냅니다. 그리고 사용자별로 키가 지정된 연결 제한기는 새로운 세션 길이보다 짧은 TTL을 가졌는데, 이는 활성 연결이 자체 카운터에서 만료되어 제한을 초과하는 추가 연결을 허용하게 됨을 의미했습니다. 두 가지 모두 원래 계획에는 없었습니다. 두 가지 모두 타임아웃 변경이 다른 어떤 부분에 영향을 미치는지 질문함으로써 발견되었습니다.

FAQ

완료 알림을 위한 pub/sub 사용에 대한 반론인가요? 아니요. Pub/sub는 '지금 브라우저에 알려주기'를 위한 합리적인 전송 수단입니다. 실수는 그것을 스토리지로 취급하는 것입니다. 만약 새로고침 후에도 응답이 유지되어야 한다면, 응답은 내구성 있는 어딘가에 존재해야 하고 ID로 가져올 수 있어야 합니다. 즉, 클라이언트가 마침 기다리고 있는 것을 키로 사용하는 재전송이 아니라, 재구성할 수 있는 ID를 가진 실제 엔드포인트가 필요하다는 뜻입니다.

왜 클라이언트만 수정하고 서버 변경은 건너뛰지 않나요? 두 버그는 서로 독립적이기 때문입니다. 일찍 구독하면 빠른 작업은 해결됩니다. 하지만 첫 번째 성공 시 스트림이 닫히는 문제, 즉 배치를 깨뜨리는 원인에 대해서는 아무런 효과가 없습니다. 각 수정 사항만으로는 재현 가능한 실패가 남게 됩니다.

터미널 상태 버그와 같은 것은 어떻게 찾나요? 설계와 일치하지 않는 지속 시간을 찾아보세요. 스트림은 30분 동안 유지되도록 구성되었지만 3초 후에 닫히고 있었습니다. 그 차이는 로그에 계속 있었지만 네트워크 불안정성으로 읽혔습니다. 장기 연결이 닫혔다는 사실뿐만 아니라 닫힌 이유를 로그로 남기세요.

상태 테이블이 있는 작업 큐가 있었다면 이 모든 것을 피할 수 있었을까요? 아마도 그랬을 것이며, 그것이 올바른 장기적인 형태입니다. 즉, 제출 시 반환되는 작업 ID, 언제든지 읽을 수 있는 상태, 그리고 결과를 알 수 있는 유일한 방법이 아닌 최적화 수단으로서의 푸시 채널 말입니다. 이는 라이브 버그 수정보다 더 큰 변경 사항이며, 압박감 속에서 어설프게 구축하기보다는 이를 연기한다고 명확히 밝히는 것이 가치 있습니다.