로그 한 줄을 못 쓴 것이 작업 실패로 기록됐습니다 — BrokenPipeError 가 OSError 라서

자사 영상 콘텐츠 프로젝트의 제작 도구를 만들고 있습니다. 로컬 웹앱에서 잡을 걸면 서버가 자식 프로세스를 띄우고, 그 자식이 외부 모델 창구에서 인물 시트와 장면 그림을 사 옵니다. 한 장마다 품질 검사를 돌려 결과를 상태 파일에 적는 구조입니다.

이날 화면에 '검사 창구 오류'가 떴습니다. 사람이 확인해야 한다는 빨간불이 켜졌습니다. 그런데 그림 파일은 멀쩡히 그려져 있었고, 산출물 옆에 남은 검사 기록에는 통과라고 적혀 있었습니다. 같은 작업을 두고 두 곳이 서로 다른 말을 했습니다.

결론부터 적으면, 그림을 사다가 난 오류도 아니고 검사를 돌리다 난 오류도 아니었습니다. 그 과정을 로그에 적으려다 난 오류였습니다. 기록하는 경로가 실행하는 경로 안에 들어 있어서, 기록의 실패가 결과의 실패로 둔갑했습니다.

산출물과 상태가 서로 다른 말을 했습니다

처음 의심한 것은 검사를 부르는 외부 창구였습니다. 그쪽이 흔들렸으면 이런 그림이 나올 수 있습니다. 그런데 창구를 부른 흔적 자체가 성공이었습니다. 응답도 받았고 판정도 받았습니다.

다음으로 본 것은 시각입니다. 그 항목이 실패로 찍힌 시각과 개발 서버가 자동 재시작된 시각이 겹쳤습니다. 저는 잡이 도는 중에 서버 코드를 저장하고 있었습니다. 코드 저장 한 번이 곧 프로세스 교체인 환경에서 10분짜리 잡을 돌린 셈입니다.

서버가 교체되자 돌고 있던 자식 프로세스의 표준 출력 파이프가 끊겼습니다. 자식은 여전히 살아서 그림을 사고 있었는데, 그 진행을 받아 적던 쪽이 사라졌습니다. 오류 종류를 열어 보니 파이프 끊김이었습니다.

파이프 끊김은 일반 OS 오류의 하위 타입입니다

파이썬에서 파이프가 끊길 때 나는 예외는 `BrokenPipeError`(표준 출력을 받아 줄 상대가 사라졌을 때 나는 오류)입니다. 그리고 이 예외는 `OSError`(파일·소켓·프로세스 같은 운영체제 자원을 다루다 나는 일반 오류)의 하위 타입입니다.

생성 단계가 항목별 오류를 수집하면서 `OSError` 를 잡고 있었습니다. 그림 파일을 못 쓰거나 임시 디렉터리에 접근하지 못하는 상황을 담으려던 자리였습니다. 그런데 그 그물에 파이프 끊김이 같이 걸렸습니다.

그래서 한 바구니에 두 가지가 담겼습니다. 하나는 '내 작업이 실패했다'이고 다른 하나는 '내가 서 있는 바닥이 사라졌다'입니다. 이 둘은 원인도 다르고 처방도 다른데, 언어 표준 예외 계층에서는 둘 다 `OSError` 입니다. 표준 예외 계층은 우리 도메인 기준으로 그려져 있지 않습니다.

이 항목의 결과는 그렇게 정해졌습니다. 그림도 있고 검사도 통과인데 상태만 실패입니다. 한 인물의 시트에서 실제로 그렇게 됐습니다.

고침 A — 기록하는 자리는 결과를 바꾸지 않습니다

첫 번째 고침은 단순합니다. 로그와 진행 기록을 쓰는 자리는 실패해도 삼킵니다. 그 자리에서 난 예외가 항목 오류 수집으로 올라가지 않게 막았습니다.

근거는 권한 문제로 봤습니다. 로그와 진행 표시는 실행 결과를 보고하는 층이지 판정하는 층이 아닙니다. 판정할 권한이 없는 층이 판정을 바꾸고 있었다면 그건 층이 잘못 놓인 것입니다. 같은 프로세스, 같은 try 블록 안에 있으면 그 경계는 저절로 무너집니다.

고침 B — 부모가 내려갈 때 자식도 정리합니다

같은 날 두 번째 갈래가 나왔습니다. 서버가 내려가도 자식 프로세스는 계속 돌았습니다. 부모 없이 3분을 더 돌면서 그림 6장을 샀습니다. 장당 약 $0.03 이 나갔고, 기록을 남길 부모가 없어 그 6장은 상태에 안 잡혔습니다.

돈은 나가고 산출물은 없는 것으로 처리되는 구간입니다. 외부 유료 창구를 부르는 자식일수록 이 구간의 손실이 즉시 금액으로 나옵니다. 그래서 자식의 수명을 부모에 묶었습니다. 서버가 내려가면 사는 것도 멈춥니다.

예외를 삼켜서 실패가 성공처럼 보였던 파이프라인을 전에 한 번 적은 적이 있습니다. 이번은 방향이 반대인데 뿌리가 같습니다. 판정하는 자리가 판정할 것이 아닌 것을 보고 있었습니다.

같은 축의 사고를 반대 방향에서 본 기록입니다.

그런데 종료가 89초 걸렸습니다

고침 B 를 붙였는데 발동하지 않았습니다. 진행 상황을 서버 전송 이벤트(SSE, 서버가 브라우저로 갱신을 흘려보내는 방식)로 바꾼 뒤부터 서버가 아예 안 내려갔습니다. ASGI 서버가 열린 스트림 연결이 닫히기를 무한정 기다렸습니다. 실측 89초였습니다.

처음 세운 원인은 '동기 제너레이터가 스레드를 잡고 있어서' 였습니다. 그럴듯했습니다. 그런데 옛 코드와 새 코드를 같은 조건으로 나란히 재 보니 아니었습니다. 그럴듯한 설명과 재 본 결과는 자주 다릅니다.

고친 방법은 두 가지를 같이 묶는 것이었습니다. 종료 대기를 3초로 끊고, 스트림 하나의 수명을 60초로 제한했습니다. 종료가 4초에 끝났습니다.

이 순서가 중요합니다. 종료를 기다리다 89초가 걸리는 상태에서는 '자식을 정리한다'를 붙여도 그 사이에 자식이 할 일을 다 합니다. 정리 코드는 있는데 정리될 대상이 이미 돈을 다 쓴 뒤입니다. 종료가 빨라져야 고침 B 가 실제로 동작합니다.

삼켜도 되는 기록과 안 되는 기록

로그 실패를 늘 삼켜도 되는 것은 아닙니다. 감사 로그, 결제 기록, 규제 대응 기록처럼 기록이 곧 산출물인 자리가 있습니다. 거기서는 쓰기 실패가 곧 작업 실패여야 맞습니다. 갈림선은 하나입니다. 이 기록이 없으면 결과가 무효인가입니다.

여기서 삼킨 것은 사람이 보라고 찍는 진행 로그였습니다. 그림 파일과 검사 기록이라는 성공 근거가 디스크에 남아 있고, 그 로그가 없다고 산출물이 무효가 되지는 않습니다.

다만 삼키면 조용해집니다. 삼킨 자리는 따로 세거나 한 번은 보이게 두는 편이 낫습니다. 기록이 몇 번 실패했는지를 아무도 모르면 다음 사고를 같은 방식으로 다시 겪습니다.

자식 수명을 부모에 묶는 것도 항상 옳지는 않습니다. 일부러 분리해 띄우는 장시간 배치라면 묶으면 안 됩니다. 여기서 묶은 이유는 자식이 남기는 기록의 종착지가 부모의 상태 파일뿐이어서, 부모가 없으면 자식의 성과가 어디에도 안 남기 때문입니다.

같은 자리를 찾는 점검 목록

이 사고는 개발 환경에서 났습니다. 그런데 운영에서도 배포 교체, 메모리 부족으로 인한 강제 종료, 컨테이너 재기동이 똑같은 모양을 만듭니다. 개발에서 먼저 보인 것일 뿐입니다. 아래 다섯 가지는 다른 시스템을 볼 때 제가 먼저 여는 자리입니다.

항목 오류를 수집하는 자리가 상위 예외 타입을 잡고 있는지 — 잡을 거면 무엇을 잡는지를 이름으로 좁힙니다

로그·진행 기록을 쓰는 코드가 결과를 판정하는 try 블록 안에 들어 있는지

산출물과 상태가 갈렸을 때 어느 쪽이 정본인지 정해져 있는지, 그리고 재검사 한 번으로 회복되는지

부모가 내려간 뒤에도 자식이 외부 유료 창구를 계속 부를 수 있는 구간이 있는지

종료에 걸리는 시간을 재 봤는지 — 정리 코드는 그 시간 안에서만 의미가 있습니다

덧붙이면, 개발 편의 기능과 장시간 잡은 정면으로 부딪힙니다. 저는 동시 생성을 3으로 올려 시트 6장 작업을 18분에서 7분 12초로 줄인 참이었습니다. 그만큼 자식이 여러 개 동시에 도는 구조가 됐고, 코드 저장 한 번이 그 전부를 끊었습니다. 잡이 도는 동안은 재시작을 막거나, 잡을 아예 다른 수명에 둡니다.

마무리

고친 것은 두 줄로 요약됩니다. 기록 실패는 결과 판정에서 뺐습니다. 자식의 수명은 부모에 묶었습니다. 검증은 플러그인 209개, 서버 98개, 웹 100개, e2e 1개 통과로 확인했습니다.

남은 것은 원인 판정을 한 번 뒤집었다는 사실입니다. 스레드를 잡고 있다는 설명은 코드를 읽으면 그럴듯했고, 나란히 재 보니 틀렸습니다. 증상이 화면에 보이는 대로 원인을 부르면 대개 그 자리에서 멈춥니다.

판정하는 쪽이 틀려서 멀쩡한 것과 고장 난 것이 뒤바뀐 사례를 따로 적어 뒀습니다.