증상 — 같은 명령을 세 번 돌렸는데 숫자가 매번 달랐다
자동화 시스템에 손을 대기 전 전체 테스트를 한 번 돌렸습니다. 1,289건이 ERROR로 끝났습니다. 실패(FAILED)가 아니라 에러(ERROR)입니다. 테스트가 틀린 답을 냈다는 뜻이 아니라, 테스트를 끝내는 과정 자체가 무너졌다는 뜻입니다.
둘의 차이가 이 글의 출발점입니다. 실패는 '답이 틀렸다'이고, 에러는 '답을 낼 수 없었다'입니다. 실패는 어디가 틀렸는지 알려 주지만 에러는 그마저 못 알려 줍니다. 그리고 에러가 수천 건 쌓이면 그 아래에 있는 진짜 실패가 보이지 않습니다.
코드를 한 줄도 안 고친 채로 다시 돌렸습니다. 이번에는 1,516건이었습니다. 한 번 더 돌리니 2,173건이었습니다. 깨지는 테스트의 이름도 매번 달랐습니다.
이 편차가 첫 단서였습니다. 코드에 버그가 있으면 같은 입력에 같은 결과가 나옵니다. 실행할 때마다 크기가 1,000건 가까이 흔들린다면 원인은 코드가 아니라 타이밍에 있습니다. 여러 작업이 동시에 돌면서 서로 순서를 밟는 자리입니다.
단서가 하나 더 있었습니다. 문제의 테스트 파일을 따로 떼어 혼자 돌리면 12건이 12건 다 통과했습니다. 전체와 함께 돌릴 때만 깨졌습니다. 개별 테스트의 버그가 아니라 무언가가 옆 테스트를 오염시키고 있다는 신호입니다.
이 상태로는 자동 검증을 신뢰할 수 없습니다. 사람이 매번 '이건 원래 그래요'라고 판단해 줘야 하는 검사는 검사가 아니라 노동입니다. 자동화를 붙이려던 작업을 멈추고 여기부터 팠습니다. 같은 계측 방식을 에이전트 실행 길이에 적용한 기록은 에이전트는 왜 한 턴 만에 멈추나에 있습니다.
처음 의심한 것 — 테스트가 실서비스 데이터베이스를 부르고 있었다
에러 하나를 열어 봤습니다. 한글이 깨질 때 나오는 낯익은 문구가 있었습니다.
UnicodeDecodeError: 'utf-8' codec can't decode byte 0x8b in position 0: invalid start byte
같이 남은 통신 기록을 보니 테스트가 실제 운영 데이터베이스에 접속하고 있었습니다. 거래 기록 테이블에 데이터를 쓰고 응답을 받는 중이었습니다. 그 응답이 압축된 형태로 오는데, 압축 데이터의 첫 바이트가 정확히 0x8b입니다.
그림이 맞아떨어졌습니다. 테스트가 바깥 서비스를 부른다, 압축된 응답이 돌아온다, 그것을 글자로 읽으려다 실패한다. 확인해 보니 접속을 만드는 자리가 코드 여덟 곳에 흩어져 있었고, 그중 테스트 중에는 부르지 말라는 방어막을 가진 곳은 한 곳뿐이었습니다.
여기서 멈추고 싶은 유혹이 큽니다. 원인이 그럴듯하고, 고칠 자리도 분명하고, 무엇보다 우리가 잘못한 일입니다. 단위 테스트가 바깥 서비스를 부르면 안 된다는 원칙에도 맞습니다. 실제로 이 시점에 사내 기록에는 '실서비스 접속이 단일 원인, 1,289건'이라고 적었습니다.
가설이 그럴듯할수록 검증을 건너뛰기 쉽습니다. 그럴듯함은 증거가 아니라 이야기의 매끄러움이고, 매끄러운 이야기는 반증을 덜 부릅니다. 실제로 이 시점의 사내 기록에는 단정형으로 적혀 있었고, 몇 시간 뒤 같은 문서에 정정이 붙었습니다.
확인에 쓴 수단 — 가짜로 갈아끼우고, 스택을 원본으로 보고, 캡처를 꺼 봤다
단정하기 전에 세 가지를 했습니다. 셋 다 '맞다'를 확인하는 도구가 아니라 '틀렸다'를 드러내는 도구입니다.
- 접속을 만드는 함수를 통째로 가짜 객체로 갈아끼웠습니다. 바깥으로 나가는 통신을 0으로 만들고 에러가 줄어드는지 봅니다.
- 오류 추적을 원본 형태로 바꿔 찍었습니다. 테스트 도구가 예쁘게 다듬은 화면은 우리 코드만 보여 주고 그 아래 층을 감춥니다.
- 출력 가로채기를 끄고 돌렸습니다. 테스트 도구는 실행 중 화면 출력을 임시로 가로채는데, 그것을 꺼서 원본 그대로 흘려보냅니다.
첫 번째가 가설을 죽였고, 두 번째가 진짜 자리를 가리켰고, 세 번째가 원인의 성격을 확정했습니다.
왜 알리바이라고 부르나 — 호출은 사라졌는데 에러는 한 건도 안 줄었다
가짜 객체로 갈아끼운 뒤 다시 돌렸습니다. 바깥 통신 기록은 깨끗하게 사라졌습니다. 갈아끼우기가 제대로 걸렸다는 뜻입니다. 그런데 에러는 1,290건이었습니다.
의심하던 범인은 현장에 있었지만 범행은 하지 않았습니다. 실서비스 접속과 에러는 같이 나타났을 뿐이고, 하나가 다른 하나를 만든 것이 아니었습니다. 함께 보인다는 사실만으로 원인을 확정한 것이 첫 오진이었습니다.
가짜로 갈아끼우기가 좋은 도구인 이유가 여기 있습니다. 이 방법은 가설을 확인하지 않고 분리합니다. 의심 대상만 세상에서 지운 뒤 증상이 남는지 봅니다. 남으면 그 대상은 원인이 아닙니다. 판정이 예·아니오로 떨어지고 해석의 여지가 없습니다.
오진을 지우지 않고 기록에 '반증됨'으로 남겼습니다. 여기서 얻은 규칙이 이후에 계속 쓰입니다. 실행마다 크기가 크게 흔들리는 장애는 단일 범인이 아니다, 자원 경합이나 교착을 먼저 의심한다.
그리고 압축 응답이 사라진 뒤에도 0x8b가 그대로 나온다는 사실이 새 질문을 만들었습니다. 압축 데이터가 아니라면 그 바이트는 어디서 왔을까.
그럼 진짜 원인은 무엇이었나 — 로그를 쓰는 손과 파일을 비우는 손이 겹쳤다
오류 추적을 원본으로 찍자 우리 코드가 한 줄도 없었습니다. 전부 테스트 도구 내부였습니다. 테스트 하나가 끝날 때마다 도구가 자기 임시 파일을 열어 읽는 자리에서 죽고 있었습니다.
출력 가로채기를 끄고 돌린 결과가 마지막 조각이었습니다. 그 상태의 출력은 처음부터 끝까지 정상적인 한글이었습니다. 깨진 데이터가 아예 없었습니다. 0x8b는 잘못된 바이트가 아니라 평범한 한글 한 글자의 뒷부분이었습니다.
정리하면 이렇습니다. 백그라운드에서 도는 작업 하나가 테스트 중에도 계속 한글 로그를 화면에 씁니다. 테스트 도구는 그 화면 출력을 임시 파일에 받아 두었다가, 테스트가 하나 끝날 때마다 파일을 처음으로 되돌리고 비웁니다. 두 동작이 겹치면 읽기 시작 위치가 한글 한 글자의 한가운데로 밀립니다.
한글은 한 글자가 여러 바이트입니다. 글자 중간부터 읽으면 첫 바이트가 시작 바이트로 보이지 않고, 그 자리에서 읽기가 예외로 끝납니다. 문제는 그다음입니다. 읽기가 예외로 끝나면 파일을 비우는 동작까지 못 하고 빠져나옵니다. 오염된 내용이 그대로 남고, 다음 테스트도 그다음 테스트도 같은 자리에서 죽습니다. 1,289건이라는 숫자는 사고 1,289건이 아니라 사고 한 건이 1,289번 번진 자국이었습니다.
실행마다 크기가 달랐던 이유도 여기서 풀립니다. 백그라운드 작업이 언제 쓰느냐는 매번 다릅니다. 겹치는 순간이 앞에서 오면 피해가 커지고 뒤에서 오면 작아집니다.
고친 방법 — 설정 한 줄, 2,172건에서 0건
원인이 파일을 두고 벌어지는 경합이라면, 그 파일을 안 쓰면 됩니다. 테스트 도구에는 출력을 가로채는 방식이 둘 있습니다. 운영체제 수준에서 임시 파일로 받는 방식이 기본값이고, 프로그램 내부에서 메모리로 받는 방식이 따로 있습니다. 뒤쪽에는 다투는 파일이 없습니다.
설정 파일에 기본 옵션 한 줄을 더했습니다. 결과는 이렇습니다.
에러 2,172건이 0건이 됐습니다. 그리고 실패 55건과 통과 5,583건은 한 건도 안 움직였습니다. 이 '안 움직였다'가 수정의 정당성입니다. 만약 통과 건수가 함께 늘었다면 문제를 가린 것이지 고친 것이 아닙니다. 사라진 2,172건이 코드의 결함이 아니라 측정 장치의 산물이었다는 증거는 여기 있습니다.
출력을 아예 끄는 선택지도 있었지만 쓰지 않았습니다. 그렇게 하면 테스트가 실패했을 때 무슨 일이 있었는지 보여 주는 기록까지 같이 사라집니다. 메모리로 받는 방식은 경합만 없애고 기록은 남깁니다.
수정 크기와 원인의 깊이는 비례하지 않습니다. 여기서 한 줄로 끝난 이유는 원인을 정확히 짚었기 때문이고, 원인을 짚기 전에 한 줄씩 고쳤다면 접속 자리 여덟 곳을 다 손대고도 숫자는 그대로였을 것입니다. 진단에 쓴 시간이 수정을 짧게 만듭니다.
고치고 나서 드러난 것 — 에러가 가리고 있던 실패 56건
에러가 걷히자 그 아래에서 실패 56건이 나왔습니다. 19개 파일에 흩어져 있었습니다. 새로 생긴 것이 아니라 원래 있었는데 위층의 에러에 가려 안 보이던 것입니다. 이것이 이런 장애의 진짜 비용입니다. 시끄러운 오류 하나가 조용한 오류 수십 개를 덮습니다.
56건을 둘로 갈랐습니다. 기준은 단순합니다. 혼자 돌려도 실패하면 테스트가 낡았고, 혼자 돌리면 통과하는데 전체에서만 실패하면 오염이 남아 있습니다.
- 낡은 테스트 49건 — 운영 코드는 멀쩡했고 테스트 쪽이 현실을 못 따라가고 있었습니다. 커밋 11건으로 정리했습니다.
- 남은 오염 8건 — 혼자서는 91건이 91건 다 통과하는데 전체 안에서만 4건이 깨졌습니다. 아직 안 잡혔습니다.
낡은 49건에서 한 갈래가 눈에 띄게 반복됐습니다. 시간에 기댄 테스트입니다. 과거 날짜를 코드에 박아 놓고 '최근 30일'처럼 오늘을 기준으로 세는 조건과 함께 쓰면, 처음에는 통과하다가 날이 지나면서 조용히 깨집니다. 보관 기한 114일이 지나 기록이 사라지면서 값이 안 맞은 사례도 같은 형태였습니다.
남은 8건은 정직하게 미해결로 적었습니다. 27분짜리 이분 탐색을 한 라운드 돌려 오염원이 앞쪽 절반에 있다는 것까지 좁혔고, 세워 둔 가설 두 개는 둘 다 틀렸습니다. 여기서 멈춘 이유는 라운드가 길어 별도 시간이 필요하기 때문입니다.
한 층 더 아래 — 테스트가 실제 운영 데이터베이스를 읽고 있었다
남은 실패를 한 달 반 뒤에 다시 잡았습니다. 단위 18건과 통합 2건이 남아 있었고, 원인이 세 가지 형태로 수렴했습니다. 셋 다 특정 코드의 버그가 아니라 테스트가 현실과 어긋나는 방식이라 다른 프로젝트에서도 같은 모양으로 나타납니다.
첫째, 운영 코드가 경로를 코드 안에 박아 두면 테스트 격리가 무력해집니다. 어댑터 하나가 생성자로 받은 디렉터리를 무시하고 운영 데이터베이스 파일을 직접 열고 있었습니다. 테스트는 임시 디렉터리를 만들어 넘겼는데 실제로는 운영 데이터를 읽었습니다. '데이터가 없을 때 빈 값' 같은 검사가 운영 데이터가 쌓일수록 조용히 깨집니다. 처음에는 통과하다가 어느 날부터 실패하는 검사는 대개 이 형태입니다.
둘째, 기능이 앞서가고 테스트가 따라오지 못하는 어긋남입니다. 조회하는 테이블이 하나에서 셋으로 늘었는데 테스트는 여전히 하나만 만들어 두거나, 호출 경로가 바뀌었는데 예전 자리에 가짜 객체를 걸어 두어 갈아끼우기가 아예 안 걸린 채 실제 데이터가 흘러드는 식입니다. 여기서 배운 함정이 하나 더 있습니다. 자동으로 속성을 만들어 내는 가짜 객체는 '그 항목이 없다'를 흉내내지 못합니다. 없는 값을 물어도 있다고 답하기 때문에, 새 설정 항목을 넣을 때는 테스트 쪽에도 그 항목을 명시해야 합니다.
셋째가 앞서 나온 시간 의존이고, 여기서는 네트워크와 겹쳐 나타났습니다. 영업일을 계산하는 함수가 과거 날짜에 대해서는 외부 시세 라이브러리를 실제로 부릅니다. 같은 파일의 다른 테스트는 그 호출을 막아 두었는데 3건만 안 막혀 있었습니다. 혼자 돌리면 통과하고 전체 안에서만 실패하는, 재현이 안 되는 실패의 전형입니다.
정리 뒤 단위 5,346건이 통과하며 남은 18건이 0이 됐고, 통합은 34건 통과에 2건이 0이 됐습니다. 둘을 합쳐 다시 돌린 결과가 5,380건 통과·12건 건너뜀·0건 실패입니다.
세 형태를 한 문장으로 줄이면 이렇습니다. 테스트가 거짓말을 하는 자리는 대개 테스트 안이 아니라, 테스트가 격리했다고 믿는 바깥과 닿아 있는 지점입니다.
같은 실수를 막는 장치 — 규칙 세 개를 코드로 내렸다
고친 것으로 끝내면 다음에 같은 자리에서 또 무너집니다. 사람의 주의력에 맡기지 않으려면 규칙이 실행되는 자리에 들어가야 합니다. 업무 흐름의 어디를 이렇게 잠글 수 있는지는 상담에서 같이 짚어 드립니다.
- 단위 테스트는 바깥 서비스에 접속하지 않는다. 새 외부 연결을 도입하면 공용 설정에 가짜 객체 등록을 함께 넣는다.
- 전체 테스트에서 에러가 급증하면 개별 버그가 아니라 연쇄를 먼저 의심한다. 혼자 돌려 통과하면 오염, 혼자서도 실패하면 진짜 버그다.
- 테스트에 과거 날짜를 박지 않는다. 오늘을 기준으로 한 상대값으로 쓴다.
두 번째 규칙은 곧바로 값을 했습니다. 한 달쯤 뒤 운영 기록에 없던 에러 2줄이 나타났습니다. 종목 코드가 가짜였고 오류 문구도 테스트에서 쓰는 값이었습니다. 실제 사고가 아니라 테스트가 운영 기록에 흘러든 것이었습니다.
원인은 방어막의 시점이었습니다. 테스트 중임을 알려 주는 표시가 실행 중에만 켜지고, 파일을 읽어들이는 단계에서는 아직 없었습니다. 파일 맨 위에서 기록기를 만드는 모듈이 다섯 곳 있었고, 그 다섯 곳이 표시가 없는 시점에 기록기를 운영용으로 굳혀 버렸습니다. 검사 신호를 세 개로 늘려 고쳤고, 수정 전 2줄이 새던 자리가 수정 후 0줄이 됐습니다.
여기서 한 가지를 일부러 안 골랐습니다. '테스트 도구가 메모리에 올라와 있으면 테스트로 간주한다'는 방법이 있습니다. 버전을 안 타서 편하지만, 운영 의존성 중 하나가 그 도구를 불러오는 순간 운영 기록이 통째로 죽습니다. 테스트가 시끄러운 것보다 운영이 조용히 눈머는 쪽이 훨씬 나쁩니다. 그래서 덜 편한 방법을 골랐고, 그 판단이 뒤집히지 않도록 반대 방향의 오탐까지 테스트로 고정했습니다.
규칙을 문서에만 적으면 다음 사람이 안 읽습니다. 셋 다 실행되는 자리에 넣었습니다. 첫째는 공용 설정 파일에서 자동으로 걸리고, 둘째는 장애 대응 순서로 굳혔고, 셋째는 검토 때 보는 항목이 됐습니다.
마지막으로 처음의 오진을 다시 봅니다. 실서비스 접속은 진짜 문제였고 고칠 값어치가 있었지만 이 사고의 원인은 아니었습니다. 둘을 구분하지 않았다면 위생 개선 하나를 해 놓고 문제가 풀렸다고 적었을 테고, 다음 실행에서 숫자가 또 흔들렸을 때 원인을 처음부터 다시 찾아야 했을 겁니다. 함께 나타나는 일과 원인인 일은 다릅니다.