10월 3일 2시 26분부터 3시 10분까지 PHP가 만드는 요청 대부분이 503이나 502로 끝났고, 2시 30분부터 몇 분 동안은 캐시에 없는 문서를 거의 열 수 없었습니다. 이 동안 503이 8,001건, 502가 1,027건 나갔습니다. 여러 주소에 퍼진 크롤러가 캐시되지 않는 문서 도구를 훑어 php-fpm 워커를 모두 차지했고, PHP 8.3으로 올리면서 커진 대기열 때문에 웹 서버가 PHP를 죽은 것으로 판단했습니다. 크롤링이 잦아들며 저절로 회복했고, 7시 7분에 대기열 상한과 속도 제한을 배포했습니다.
| 시각 | 일어난 일 |
|---|---|
| 02:15 | 로그인하지 않은 Chrome 요청이 늘기 시작함 |
| 02:20 | php-fpm 워커 16개가 전부 점유되고 웹 서버의 CPU가 99%에 닿음. 데이터베이스 서버는 한가함 |
| 02:21 | 특수:새항목 요청이 페미위키 자신의 API를 부르다 25초 만에 시간 초과로 끝난 첫 기록 |
| 02:24 | 워커 대기열이 1,785에 이름 |
| 02:26 | Caddy의 /healthz.php 확인이 시간 안에 답을 받지 못해 503이 나가기 시작함
|
| 02:30 | 대기열이 상한인 4,096에 닿음. 503이 분당 1,300건 안팎으로 가장 많음 |
| 02:36 | 다른 작업을 확인하던 워커가 발견함 |
| 03:10 | 마지막 502와 503. 크롤링이 잦아들어 저절로 회복함 |
| 07:07 | 대기열 상한과 속도 제한을 배포함[1] |
원인
로그인하지 않았고 Accept-Language가 zh-CN인 Chrome 요청이 2시 15분 무렵부터 10분에 840건쯤에서 2,490건으로 세 배가 됐습니다. 2시 15분부터 10분 동안 이 요청은 2,964개 주소에서 왔고 주소 하나가 한 번 남짓만 요청했으므로, /24별 제한에는 걸리지 않았습니다. 요청한 것은 편집과 주시, 기여자, 특수:링크최근바뀜, 특수:이문서인용, 특수:새항목, 그리고 /w/ 꼴의 특수:가리키는문서처럼 문서마다 사이드바에 걸린 도구였습니다. 어느 것도 캐시되지 않고, 9월 30일 사고 뒤에 넣은, 로그인하지 않은 빨간 링크와 특수:가리키는문서 요청을 사이트 전체에서 세는 link_walk 제한은 특수:가리키는문서를 title= 꼴로만 셌으므로 아무 한도도 받지 않았습니다.[2] 특수:새항목은 위키베이스가 문서 이름을 확인하려고 페미위키의 api.php를 다시 부르므로, 요청 하나가 워커 두 개를 차지하고 워커가 모자랄 때는 25초를 기다립니다.
9월 30일에도 같은 방식으로 워커가 모두 찼지만 그때는 느려지기만 했습니다. 이번에 503까지 간 것은 php-fpm이 받아 두는 대기열의 상한이 10월 2일 23시 48분 PHP 8.3 배포와 함께 511에서 4,096으로 커졌기 때문입니다.[3] 몇 분어치 요청이 줄을 서자 웹 서버가 1초마다 보내는 /healthz.php 확인도 10초 안에 답을 받지 못했고, 웹 서버는 두 PHP 포트를 모두 빼고 503을 돌려주었습니다. 줄에 선 요청은 이용자가 떠난 뒤에도 처리되어 워커를 계속 붙잡았습니다.
수치는 모두 Loki의 Caddy 접근 로그와 Grafana Cloud의 php-fpm 지표, CloudWatch의 CPU 지표에서 잰 것입니다. 429로 거절된 요청은 접근 로그에 남지 않으므로 위 건수에 들어 있지 않습니다.
고친 것
- php-fpm 대기열을 64건으로 묶어, 넘치는 요청은 웹 서버가 바로 실패로 처리하고 확인 요청이 줄 뒤에 갇히지 않게 했습니다. 로그인하지 않은 편집, 주시, 기여자, 특수:링크최근바뀜, 특수:이문서인용, 특수:새항목,
/w/꼴의 특수:가리키는문서 요청을 사이트 전체에서 10분에 150건까지 받는page_tools제한을 넣었습니다. infra#1058에서 고쳐 7시 7분에 배포했고, 배포 뒤 대기열 상한이 64로 바뀐 것을 확인했습니다.
남은 문제
- 크롤링이 이어지는 동안에는 위 도구를 여는 로그인하지 않은 이용자도 크롤러와 같은 한도에서 429를 받을 수 있습니다. 로그인한 이용자는 제한을 받지 않습니다.