0/13이라는 숫자

Zenn에 공개된 기사 15편에 수정을 가했다. 수치 정정이나 정보 업데이트 등인데, 이미 공개된 기사를 건드린 이상 "정말로 사이트에 반영되었는가"를 기계적으로 확인하고 싶었다. 일일이 수동으로 열어서 눈으로 확인하는 것은 번거로우므로, 운영 URL을 curl로 가져와서 수정 후의 문자열이 포함되어 있는지 grep으로 판정하는 검증 스크립트를 작성했다.

수정 내용으로부터 일의적으로 판정할 수 있는 문자열을 고를 수 있었던 것은 13편. 실행 결과는 0/13이었다. 전멸이다.

순간 "수정이 전부 사이트에 반영되지 않았다"라고 결론을 내릴 뻔했다. 배포 메커니즘이 고장 난 것인지, 캐시가 옛날 상태 그대로인지, 머릿속으로 원인 후보들을 나열하기 시작했다. 하지만 손이 멈췄다. 0/13이라는 숫자가 이상하다.

전멸은 검출 측을 의심하라

수정 내용 중 몇 편은 몇 분 전에 직접 브라우저를 열어 반영을 확인했었다. 즉 "사이트 측은 고쳐져 있다"는 것을 이미 알고 있다. 그런데도 스크립트는 0/13을 반환한다. 양쪽 모두가 맞을 수는 없다.

여기서 멈출 수 있었던 것은 단순한 경험칙 덕분이다. 검증 결과가 "전멸" 혹은 "전체 일치"와 같이 극단적인 형태가 되었을 때는, 먼저 검증 대상이 아니라 검증 스크립트 자체를 의심한다. 100%의 실패도 100%의 성공도, 실제 데이터에서는 그렇게 빈번하게 나타나지 않는다. 나타났을 때는 대개 판정 로직의 어딘가가 계통적으로 고장 나 있다.

의심하며 스크립트를 다시 읽어본 결과, 원인은 2가지 발견되었다.

원인 1: CRLF 혼입

검증 스크립트를 Windows 측에서 생성했기 때문에 개행 코드(Line Ending)가 CRLF로 되어 있었다. 기사의 슬러그(slug)와 확인하고 싶은 문자열의 쌍을 slug|needle 형식으로 출력하고, 다음 형태로 루프를 돌렸다.

while IFS='|' read -r slug needle; do
...
done < records.txt

needle의 끝에 복귀 문자(Carriage Return)가 남은 채로 grep에 전달되었다. 운영 페이지의 HTML에는 복귀 문자가 포함되지 않으므로, 일치해야 할 문자열이 일치하지 않게 된다.

이것은 깨달으면 바로 고칠 수 있는 종류의 버그이며, 읽어들이는 측에서 제거하면 끝난다.

needle=$(printf '%s' "$needle" | tr -d '\r')

하지만 이번에는 이것이 주된 원인이 아니었다. 복귀 문자를 제거해도 결과는 0/13 그대로였기 때문이다.

원인 2: pipefail와 grep -q가 맞물리지 않음

본래의 원인은 이것이었다. 검증 스크립트의 핵심은 다음과 같은 형태였다.

set -uo pipefail
body=$(curl -s "$url")
printf '%s' "$body" | grep -qF "$needle"
...

grep -q는 "일치하는지 여부만 알고 싶고, 출력은 필요 없다"라고 할 때의 정석이다. 일치하는 순간 탐색을 중단하고 종료하므로 빠르다는 것이 장점이다. 그런데 이 "일치하면 즉시 종료한다"는 동작이 파이프(pipe)의 상류(upstream)에 있는 printf에게는 불리하다.

grep이 입력을 끝까지 읽지 않고 파이프의 읽기 측을 닫아버리면, 쓰기 측인 printf는 보낼 수 없게 된 데이터를 품은 채로 SIGPIPE (시그널 번호 13)를 받고 종료된다. 시그널로 종료된 프로세스의 종료 코드(exit code)는 관습적으로 128 + 시그널 번호가 되므로, 128 + 13 = 141이 반환된다.

pipefail을 활성화하면 파이프 전체의 종료 코드는 "파이프 안에서 마지막으로 실패한 커맨드의 종료 코드"가 된다. 즉 printf가 141로 떨어지면 파이프 전체도 141이 되며, 0이 아니므로 "실패" 취급을 받는다.

이 부분이 함정의 핵심이다.

• 일치하지 않을 경우: grep이 입력을 끝까지 다 읽으므로 printf는 정상 종료되고, grep 자신의 종료 코드(불일치라면 1)가 그대로 결과가 된다.
• 일치할 경우: grep이 도중에 중단하므로 printf가 SIGPIPE로 141이 되어, 파이프 전체가 실패로 판정된다.

일치/불일치에 따라 반환되는 종료 코드의 의미가 뒤바뀐다. curl을 끼워 넣지 않아도 다음 커맨드로 재현할 수 있다.

$ set -o pipefail
$ seq 1 1000000 | grep -q 5
$ echo $?
...

seq는 대량의 행을 쏟아내려 하지만, grep -q는 5를 포함하는 행을 빠른 단계에서 찾아내고 중단한다. seq

는 아직 쓰려고 하는 데이터를 품은 채 SIGPIPE를 받고 141로 종료되며, pipefail이 이를 포착한다. 매칭되었음에도 종료 코드는 실패인 상태가 발생한다.

조건: 상류의 출력이 파이프 버퍼(pipe buffer)에 담기지 않을 것

단, 이것은 무조건 발생하는 것은 아니다. 동일한 명령어를 입력 크기만 바꿔서 실행해 보면 명확한 임계값이 존재한다.

$ for n in 10 1000 10000 50000 100000; do
printf 'N=%-7s → ' "$n"
bash -c "set -o pipefail; seq 1 $n | grep -q 5; echo \$?"
...

작은 입력에서는 141이 되지 않는다. 이유는 출력 전체가 파이프 버퍼에 담기면, seq는 쓰기를 마치고 정상 종료될 수 있기 때문이다.

grep이 언제 중단하더라도, 쓰기 측은 이미 더 쓸 것이 남아있지 않으므로 SIGPIPE를 받을 일이 없다. 즉, 이 함정이 발동하는 조건은 "상류가 아직 쓰고 있는 도중에 하류가 닫히는 것"이며, 그러기 위해서는 상류의 총 출력이 파이프 버퍼를 초과해야 한다. 내 환경에서 getconf PIPE_BUF /는 4096을 반환했지만, 실제로 임계값이 나타난 것은 1만~5만 행 사이였다. PIPE_BUF는 "원자적(atomic)으로 쓸 수 있는 최대 크기"이지 버퍼 전체의 용량이 아니므로, 이 수치를 그대로 임계값으로 생각하지 않는 것이 좋다.

내가 겪은 케이스에서는 취득한 HTML이 약 127KB였다. 파이프 버퍼에 담기지 않는 크기였으므로 조건을 충족했다.

작은 데이터로 테스트하면 재현되지 않으므로, 동작 확인 시에는 실제 데이터 크기로 테스트할 필요가 있다. 이 점 또한 함정의 일부라고 생각한다.

내 케이스에서는 curl로 취득한 HTML이 충분히 커서, grep -qF가 빠른 단계에서 일치 항목을 찾아 중단할 때마다 printf가 SIGPIPE를 받고 있었다. 반대로 일치하지 않는 기사에서는 grep이 끝까지 다 읽기 때문에 printf는 정상 종료되고, grep의 1이 그대로 결과가 된다.

결과적으로 "반영된 기사일수록 실패 판정이 나는" 상태, 즉 판정의 의미가 통째로 반전된 상태가 되어 있었다. 이것으로 0/13을 설명할 수 있다.

수정 방법은 파이프를 그만두는 것이었다.

grep -qF "$needle" <<< "$body"

Here-string에는 파이프의 상류에 해당하는 프로세스가 존재하지 않는다. 데이터는 셸이 준비한 입력으로서 grep에 전달되므로, grep이 어디서 스캔을 중단하더라도 쓰기 측에서 SIGPIPE를 받을 프로세스가 애초에 없다.

실제로 확인해 보니, 작은 입력이든 큰 입력이든 일치하면 0을 반환한다.

$ body=$(seq 1 1000000)
$ set -o pipefail
$ grep -q 5 <<< "$body"; echo $?
...

(내부적으로 임시 파일을 사용하는지 여부는 셸의 구현에 따라 다르다. 여기서 확인한 것은 "SIGPIPE가 발생하지 않는다"는 동작까지이며, 구현의 상세 내용까지는 추적하지 않았다.)

왜 알아채기 어려운가

이 버그의 까다로운 점은 "일치했을 때만 실패한다"는 반전 구조에 있다. "매칭되면 성공, 매칭되지 않으면 실패"라는 솔직한 대응을 기대하게 되지만, 실제로는 조건이 반대가 되는 상황이 발생한다.

게다가 동작 확인 순서가 이 버그를 숨기는 방향으로 작용한다. 사람은 아무래도 "매칭되지 않는 케이스"를 먼저 테스트하기 마련이다. "아직 반영되지 않은 상태에서 제대로 실패 판정이 나는가"를 확인하고 만족해 버린다. 이 확인은 올바르게 통과한다. 불일치 시에는 grep이 끝까지 다 읽으므로 파이프가 정상적으로 완결되기 때문이다.

버그가 얼굴을 내미는 것은 "매칭되는 케이스"를 테스트할 때뿐인데, 그것은 대개 "이미 수정한 후"에 확인하는 단계이므로 뒤로 밀리기 쉽다. 테스트 순서 자체가 버그를 숨기고 있었던 것이다.

수정 후의 결과

파이프를 배제하고 재실행하자 13개 중 11개가 반영된 것으로 판정되었다. 남은 2개를 개별적으로 조사한 결과, 내역은 갈렸다.

1개는 검색 문자열을 잘못 선택한 것이었다. 그림 안의 라벨을 찾고 있었으나, 그 부분은 본문과는 다른 형태로 렌더링되어 있어 단순한 문자열 일치로는 잡아낼 수 없었다. 삭제했을 터인 구형 기술이 사라진 것을 별도로 확인하여 반영된 것으로 판단했다.

나머지 하나는 정말로 반영되지 않은 상태였다. 원인은 검증 스크립트가 아닌 다른 곳에 있었는데, 수정 시의 문자열 치환(string replacement)이 대상과 일치하지 않아 헛스윙을 하고 있었다. 파일의 내용은 바뀌지 않았는데, 변경 이력에는 「수정 완료」라고 적혀 있는 상태였다. 이것은 검증 스크립트가 제대로 작동하여 찾아낸 진짜 버그였으며, 이를 수정하고 다시 반영 여부를 확인했다.

최종적으로 13개 중 12개는 처음부터 반영되어 있었고, 1개는 수정 자체를 다시 할 필요가 있었다.

같은 날 저지른 또 다른 검증 실수

같은 날, 또 하나의 검증 실패를 저질렀다. 어떤 목록의 개수를 셀 필요가 있었는데, 조잡한 정규 표현식 (regular expression)으로 카운트하여 13개라는 결과를 얻었다. 이 숫자를 다른 집계와 대조해 보고 「차이가 난다, 검증으로 잡아냈다」라고 판단하여 그대로 기사 초안에 적었다.

리뷰에서 지적을 받고 다시 세어 보니, 유니크한 ID (unique ID)로 세면 12개였다. 정규 표현식이 제목 행을 중복으로 拾고(pick up) 있었을 뿐, 차이가 났던 것은 나의 계산 방식이었다. 게다가 그것을 「검증이 효과가 있었다는 증거」로 기사에 적었기 때문에, 대책의 유효성을 보여주는 예시가 근거 없는 상태가 되어버렸다.

이날은 똑같은 「검증 결과를 액면 그대로 믿는」 실수를 방향을 달리하여 두 번 저질렀다. 첫 번째는 「전멸이라는 극단적인 결과」를 의심하여 멈춰 설 수 있었다. 두 번째는 「다른 숫자와 차이가 난다」라는 일견 그럴듯한 결과에 달려들어, 자신의 계산 방식이 허술함을 간과했다.

일반화된 교훈

검증 결과가 「전멸」, 「전부 일치」와 같이 극단적인 형태로 나왔을 때는, 우선 검증 방법 그 자체를 의심한다. 이것은 이번에 제대로 작동했다.

하지만 이 경험칙은 극단적인 숫자에만 반응한다. 두 번째 사례처럼 그럴듯한 범위 안에 들어오는 숫자가 나와 버리면 단서가 없어진다. 극단성에 의존하지 않는 대책이 필요하다.

실천하고 있는 것은, 검증 스크립트를 실제 데이터에 돌리기 전에, 정답을 알고 있는 기지의 케이스 (known case)에서 한 번 실행해 보는 것이다. 「반드시 일치해야 하는 쌍」과 「절대 일치해서는 안 되는 쌍」을 모두 준비하여, 기대한 대로 결과가 반환되는지를 먼저 확인한다. 이번 버그의 경우라면, 일치하는 케이스를 테스트에 포함했다면 그 자리에서 바로 알아차릴 수 있었을 것이다.

또 하나는, 파이프 (pipe) 안에 「입력을 끝까지 읽지 않을 가능성이 있는 커맨드 (command)」를 둘 때, pipefail과 grep -q의 조합을 한 템포 쉬고 생각하는 것이다. grep -q, head, sort -u와 같이 조기 종료될 수 있는 커맨드가 파이프의 하류 (downstream)에 있는 구성에서는, here-string이나 프로세스 치환 (process substitution)으로 대체할 수 없는지를 우선 의심하도록 하고 있다.

검증하는 측이 틀렸을 가능성은, 검증 대상이 틀렸을 가능성만큼이나 항상 존재한다.

좋아요나 댓글로 반응해 주시면 큰 힘이 됩니다!

Discussion