10월 4일 0시 22분부터 1시 15분까지 웹 서버와 PHP 컨테이너를 네 번 교체했고, 교체할 때마다 1분 남짓 동안 캐시에 없는 문서를 연 이용자가 502나 503을 받았습니다. 교체 네 번에서 나간 오류는 742건입니다. 새 PHP 워커가 1초에 하나씩만 늘어 요청을 받지 못했고, 새 웹 서버는 요청 제한 기록을 넘겨받지 못해 크롤러를 막지 못했으며, 옛 웹 서버는 처리하던 요청을 마치지 못하고 꺼졌습니다. 세 가지를 모두 고친 뒤 9시 46분 교체에서는 오류가 한 건도 나가지 않았습니다.
| 시각 | 일어난 일 |
|---|---|
| 00:20 | 교체와 관계없는 크롤링으로 1분 동안 502 138건, 503 60건이 나감 |
| 00:22 | 52번째 교체.[1] 1분 동안 502 209건, 503 90건 |
| 00:32 | 교체와 관계없는 크롤링으로 1분 동안 502 169건, 503 36건이 나감 |
| 00:38 | 새 PHP 워커를 처음부터 16개로 띄우는 53번째 교체.[2] 30초 동안 502 111건, 503 46건 |
| 00:47 | 54번째 교체.[3] 1분 20초 동안 502 137건, 503 29건 |
| 00:57 | 교체 없이 502 16건, 503 6건이 나감 |
| 01:14 | 웹 서버가 PHP 워커를 10초까지 기다리게 한 55번째 교체.[4] 1분 동안 502 120건, 503은 없음 |
| 09:46 | 옛 웹 서버가 요청을 마저 처리하고 요청 제한 기록을 넘겨받는 56번째 교체.[5] 오류 없음 |
0시 20분부터 1시 25분까지 나간 502와 503은 모두 1,167건이고, 그 가운데 742건이 교체 때, 425건이 교체가 없던 0시 20분, 32분, 57분에 나갔습니다. 이 보고서는 교체가 만든 742건을 다루고, 나머지는 아래 남은 문제에 적었습니다. 10월 3일 낮의 교체 다섯 번에서도 한 번에 4건에서 53건씩 오류가 나갔습니다.[6]
원인
교체는 새 웹 서버(Caddy)와 새 php-fpm을 띄워 요청을 옮긴 뒤 옛 컨테이너를 지웁니다. 이때 세 가지가 겹쳤습니다.
새 php-fpm은 워커 2개로 시작하고, 바쁠 때 1초에 하나씩만 워커를 늘렸습니다. pm.min_spare_servers가 1이었으므로 php-fpm이 한 번에 늘리는 수도 1이었습니다.[7] 요청을 모두 넘겨받은 새 풀이 상한 16개에 닿기까지 11초쯤 걸렸고, 그 사이 대기열 64건이 넘쳐 웹 서버는 3초 연결 시간 초과를 두 번 겪은 뒤 502를 돌려주었습니다. 풀이 가득 차면 웹 서버가 PHP 상태를 묻는 /healthz.php도 답을 받지 못해, 두 풀을 모두 빼고 503을 돌려주었습니다.
새 웹 서버는 요청 제한을 처음부터 다시 셌습니다. 웹 서버들은 제한 기록을 S3에 남겨 다음 세대가 읽게 되어 있었지만, 저장 모듈이 파일을 쓸 때는 앞에 붙이는 경로를 목록을 읽을 때는 붙이지 않아 아무것도 찾지 못했습니다. 그래서 교체 직후에는 옛 웹 서버가 막던 크롤러 요청이 그대로 PHP로 갔습니다. 55번째 교체 직후 50초 동안 편집 화면과 빨간 링크 요청 154건이 PHP에 닿았고, 그 전 50초에는 한 건도 없었습니다.
옛 웹 서버는 처리하던 요청을 마치지 못하고 강제로 꺼졌습니다. 컨테이너를 멈추는 신호를 받은 시작 스크립트가 웹 서버에 신호를 넘기지 않고 먼저 끝났기 때문입니다. 끊긴 요청은 php-fpm이 계속 처리하며 교체 중의 워커를 붙잡았습니다.
수치는 모두 Grafana Cloud Loki에 남은 웹 서버 접근 로그(http-51부터 http-55까지)에서 상태 502, 503, 504를 센 것입니다. 504는 없었습니다.
고친 것
- 새 php-fpm을 처음부터 워커 16개로 띄우고 한가해도 줄이지 않게 했습니다. infra#1122에서 고쳐 0시 38분 교체부터 적용했고, 오류가 299건에서 157건으로 줄었습니다.
- 웹 서버가 PHP 연결을 바로 포기하지 않고 10초까지 기다리게 했습니다. infra#1135에서 고쳐 1시 14분 교체부터 적용했고, 503이 없어졌습니다.
- 옛 웹 서버가 처리하던 요청을 마치고 꺼지게 했습니다. docker-mediawiki#1305에서 고쳐 9시 46분 교체부터 적용했고, 옛 웹 서버가 꺼지는 데 1초 대신 12초가 걸린 것을 확인했습니다.
- 새 웹 서버가 이전 세대의 요청 제한 기록을 읽게 했습니다. docker-mediawiki#1308에서 고쳐 infra#1142로 9시 46분에 배포했고, 새 웹 서버가 첫 20초부터 모든 제한에서 요청을 거절한 것을 확인했습니다. 이 교체에서 나간 5xx는 없습니다.
남은 문제
- 교체가 없어도 크롤링이 몰리면 워커 16개가 모자라 오류가 나갑니다. 이번에도 0시 20분, 32분, 57분에 425건이 나갔습니다. infra#624에서 다룹니다.
출처
- ↑ https://github.com/femiwiki/infra/pull/1122
- ↑ https://github.com/femiwiki/infra/pull/1122
- ↑ https://github.com/femiwiki/infra/pull/1132
- ↑ https://github.com/femiwiki/infra/pull/1135
- ↑ https://github.com/femiwiki/infra/pull/1142
- ↑ https://github.com/femiwiki/infra/issues/1121
- ↑ https://github.com/php/php-src/blob/2d3433d24d59f45703be2b4fb40d74e5a41b136b/sapi/fpm/fpm/fpm_process_ctl.c#L422