끄적임 CI 고치다 PR이 15개 쌓인 날: #129부터 #144까지 실패 일지

러너를 옮기고 CI를 돌렸더니 1시간 넘게 돌다 죽었다. 한 줄 고치고 재실행, 또 실패, 또 한 줄. 하루가 지나고 보니 PR 번호가 #129에서 #144까지 올라가 있었다. 결과편("CI 46초")이 아니라, 그 과정의 실패 일지다.

0. 배경: 러너를 옮겼다

AIFid 저장소의 GitHub 조직을 옮기면서(pushwing → aivance-kr) CI 러너도 macOS ARM64에서 self-hosted Linux X64로 바꿨다. #129는 단순한 PR이었다. 수동 docker run과 정리 스텝을 services: 블록으로 바꾸고, runs-on만 갈아 끼웠다.

문제는 이 변경이 feature → dev 머지 때는 CI가 돌지 않는다는 점이다. 이 저장소의 CI는 dev → main 배포 PR(#130)에서 처음 돈다. 그러니 #129의 검증은 전부 #130에서 일어났고, 이후 PR 열댓 개는 사실상 "#130을 초록불로 만들기 위한 수정"이었다.

이하 시각은 모두 2026-09-04(KST)다.

1. 12:47 · #131 ci-needrestart-fix — 30분 넘게 아무 일도 안 일어난다

#130의 백오피스 잡이 setup-php 단계에서 멈췄다. 30분이 지나도 로그가 없었다. 러너 Worker 로그를 보니 apt 설치 도중 needrestart의 대화형 프롬프트가 입력을 기다리고 있었다. CI에는 키보드가 없으니 영원히 기다린다.

NEEDRESTART_MODE: a를 잡 환경변수에 넣었다. 프롬프트 자체를 없애는 한 줄이다.

2. 13:38 · #132 ci-php-native-install — 이번엔 PPA다

다음 실행도 같은 자리에서 멈췄다. 러너 박스에서 직접 재현해 보니 이유가 달랐다. 러너 OS가 Ubuntu 26.04(코드명 resolute)였는데, ondrej/php PPA가 아직 이 코드네임을 지원하지 않았다. apt-get update가 "Release 파일 없음"으로 실패하고, setup-php는 그걸 무한 재시도했다.

그런데 resolute 네이티브 저장소에 이미 PHP 8.5, composer, 필요한 확장 대부분이 들어 있었다. setup-php를 걷어내고 apt로 직접 설치하도록 바꿨다. 러너 박스에 잘못 등록된 PPA 소스 파일도 지웠다.

이 PR의 위험 항목에는 "PHP 타겟이 사실상 8.2에서 8.5로 올라간다"고 적었다. 8.5의 새 deprecation 때문에 PHPStan이나 PHPUnit이 새로 걸릴 수 있다고 봤는데, 다행히 이 걱정은 맞지 않았다. 진짜 문제는 다른 곳에 있었다.

3. 16:14 · #133 ci-add-sqlite3 — composer가 확장을 요구한다

설치 단계가 드디어 끝나고 composer install까지 갔다. 그리고 바로 실패했다.

setup-php가 기본으로 깔아 주던 확장이 apt 네이티브 설치로 바꾸면서 빠진 것이다. 설치 목록에 php-sqlite3를 추가했다. 이 교훈은 이후 다른 저장소의 CI 문서에도 옮겨 적었다. 확장 목록은 감으로 쓰지 말고 composer.lock의 ext-* 요구에서 뽑는다.

4. 17:33 · #134 ci-mysql-healthcheck-fix — 765개가 전부 Connection refused

처음으로 PHPUnit이 실제로 돌았다. 그리고 765개가 전부 Connection refused로 죽었다.

가설은 그럴듯했다. MySQL 8 이미지는 초기화 중에 소켓만 여는 임시 서버를 먼저 띄운다. 소켓 기반 healthcheck가 이 임시 서버에서 먼저 통과하고, 진짜 서버로 재시작하는 짧은 틈에 PHPUnit이 접속을 시도해 거부당했다는 설명이다. --health-cmd에 -h 127.0.0.1을 붙여 TCP 접속을 강제했다.

결과는 같았다. 이 가설은 틀렸다.

5. 17:49 · #135, 18:07 · #136 — 진단용 PR이 두 개

컨테이너 로그를 보면 healthy 판정 전에 이미 진짜 서버가 3306에서 떠 있었다. 임시 서버 가설로는 설명이 안 됐다. 추측을 멈추고 CI 안에서 직접 보기로 했다.

• #135 (임시): getenv() 값과 실제 TCP 접속 가능 여부를 출력하는 진단 스텝을 넣었다. 결과는 이상했다. 순수 getenv()와 PDO 접속은 성공하는데, bootstrap.php의 PDO 접속만 실패했다.
• #136 (임시): bootstrap.php가 예외 클래스명만 찍고 메시지를 안 찍고 있었다. $e->getMessage() 출력을 추가했다.

CI에서 "한 줄 찍고 재실행"은 한 번에 5~10분이 든다. 진단 PR을 둘 올리는 동안 한 시간이 지나갔다. 이 시점부터는 가설을 세우기 전에 로컬에서 재현하는 쪽이 싸다는 걸 체감했다.

6. 18:30 · #137 — 반쪽짜리 원인

로그를 읽다 보니 단서가 나왔다. phpunit.dist.xml의 <env>는 force="true"가 아니어도 PHP 프로세스의 $_ENV와 $_SERVER에는 항상 XML 값을 심는다. CI4의 env()와 bootstrap.php의 $read()는 둘 다 $_SERVER → $_ENV → getenv() 순으로 읽는다. CI가 export한 값(13306, root/root)이 있어도 XML의 로컬 기본값(3307, aifid/aifid)이 항상 이긴다.

XML에서 hostname, port, username, password <env>를 지웠다. 그럴듯한 설명이었고 머지까지 했다. 그런데 이것도 절반만 맞았다.

7. 18:38 · #138 ci-db-target-guard — 진짜 원인

로컬에서 재현했다. 이번에는 PR 본문에 "로컬 재현으로 확정"이라고 쓸 수 있었다.

CI4는 database.tests.hostname처럼 점이 들어간 이름으로 설정을 읽는다. 그런데:

1. PHP는 점이 들어간 이름을 $_SERVER와 $_ENV에 넣지 않는다. getenv()로만 보인다.
2. Composer는 자식 프로세스 환경을 array_intersect_key(getenv(), $_SERVER)로 만든다.
3. 그래서 composer test로 PHPUnit을 띄우는 순간 점 이름은 통째로 사라진다.

즉 CI 워크플로가 넘긴 접속 정보는 PHPUnit 프로세스에 한 번도 도달한 적이 없었다. 테스트는 phpunit.dist.xml의 로컬 기본값(3307)으로 폴백했고, 맥 러너에서는 거기에 개발자의 로컬 개발 DB가 떠 있었다. 그래서 초록불이었다.

여기서 소름 돋는 부분이 있다. 이 테스트 베이스는 $refresh = true라서 클래스마다 regress → migrate를 돌린다. 과거의 CI는 초록불을 내는 동시에 로컬 개발 DB를 지웠다 다시 만들고 있었을 가능성이 높다. 러너를 옮기지 않았다면 영영 몰랐을 버그다.

수정은 세 가지였다.

• ci.yml: 접속 정보를 밑줄 이름(database_tests_*)으로 넘긴다. 유효한 변수명이라 Composer를 거쳐도 살아남는다.
• tests/bootstrap.php: 밑줄 이름을 CI4가 읽는 점 이름으로 옮긴다. 이미 점 이름이 있으면 건드리지 않는다.
• DatabaseTargetTest: 환경이 요청한 접속 정보와 프레임워크가 실제 쓰는 값이 다르면 실패시킨다. CI인데 아무것도 전달되지 않은 경우도 실패시킨다. 이번 사고가 정확히 그 모습이었다.

마지막 항목이 이날 가장 값진 결과물이다. 고친 것보다 "다시 조용히 틀어지면 빨간불이 켜진다"는 장치를 남긴 것이 오래 간다.

8. 18:52 · #139 fix-cs-bootstrap — PSR-12 한 줄

#138을 머지한 직후 bootstrap.php의 PSR-12 정렬이 CS 검사에 걸렸다. 로컬에서 composer check를 안 돌리고 올린 대가다. 내용은 공백 정렬이 전부라 쓸 말이 없다. 그래서 PR 번호 하나가 더 늘었다.

9. 19:24 · #140 ci-mysql-instrumentation — 이제 테스트가 돈다, 그런데

접속이 풀리고 테스트가 실제로 돌기 시작했다. 250개 넘게 정상 통과했는데, 그 뒤로 나머지가 전부 MySQL server has gone away로 죽었다.

OOM은 아니었다(30GB 중 24GB 여유, dmesg에 kill 없음). 디스크도 아니었고(817GB 여유), 잡 동시 실행도 아니었다. 서버가 죽은 건지 커넥션이 바닥난 건지 로그만으로는 갈리지 않아서, 5초마다 MySQL 상태를 샘플링하는 계측을 넣었다. 또 한 번의 임시 PR이다.

10. 23:01 · #141 fast-test-schema — 범인은 DB가 아니었다

계측 결과가 나왔다.

• MySQL은 한 시간 내내 멀쩡했다. 커넥션 2~3개 고정, abort 0, 종료 시점에도 mysqld is alive.
• 테스트도 378개까지 전부 통과 중이었다.
• 실패 원인은 The process "phpunit" exceeded the timeout of 3600 seconds였다. Composer의 프로세스 타임아웃이다.

"gone away"는 타임아웃으로 프로세스가 죽는 순간 따라 나온 증상이었다. 진짜 문제는 스위트가 너무 느리다는 것이었다. CI4의 $refresh = true는 클래스가 아니라 테스트 메서드마다 전체 regress → migrate를 돈다. 마이그레이션 38개에 DB를 쓰는 테스트가 수백 개라 DDL이 수만 건이고, InnoDB의 DROP/CREATE는 파일 조작이라 건당 수십 ms가 든다. 실측으로 MySQL이 567초 동안 테이블을 4,707번 열었다. 맥에서도 같은 비용이었고(7월 배포 run이 18분 45초), 디스크가 빨라서 덜 아팠을 뿐이다.

스키마는 프로세스당 한 번만 만들고($migrateOnce = true), 테스트마다 TRUNCATE로 데이터만 비우는 트레이트를 만들었다. "빈 DB로 시작한다"는 기존 전제가 그대로라 테스트 코드는 한 줄도 고치지 않았다.

같은 작업이 병렬로 한 번 더 진행되고 있었다. #142(fast-db-test-reset)가 같은 날 같은 시각에 같은 아이디어로 열려 있었고, #141이 먼저 머지되어 #142는 닫혔다. 세션을 나눠 돌리면 이런 중복이 생긴다.

11. 23:14 · #143 — 같은 패턴, 다른 곳

#141 덕에 1시간 넘게 돌던 잡이 9분 40초에 끝까지 갔다. 915개 중 실패는 4개였고, 원인은 하나였다. ReassignToReturningAgentJobTest가 Redis 포트를 6389(로컬 docker-compose 값)로 하드코딩하고 $_ENV/$_SERVER까지 그 값으로 덮어쓰고 있었다. 맥에서는 6389에 로컬 개발 Redis가 떠 있어서 우연히 통과했고, 지금까지는 DB 단계에서 먼저 죽어서 여기까지 온 적이 없었다.

DB 접속에서 겪은 것과 정확히 같은 패턴이다. 접속 대상은 환경 변수가 정하고, 지정이 없을 때만 로컬 기본값으로 폴백하도록 고쳤다.

12. 23:28 · #144 ci-xdebug-coverage — 915개 통과하고도 실패

에러가 686개에서 4개로, 4개에서 0개로 줄었다. 그런데 잡은 여전히 빨간불이었다.

경고는 XDEBUG_MODE=coverage has to be set 하나였다. phpunit.dist.xml이 failOnWarning="true"라서 경고가 곧 실패다. 예전 macOS 러너에서는 setup-php의 coverage: xdebug가 켜 줬는데, apt 설치로 바꾸면서 같이 사라진 설정이었다. XDEBUG_MODE: coverage를 env에 추가했다.

이제 정말 초록불이다. 9분 24초.

13. 다음 날 · #145 — 이왕 보는 김에 28초까지

초록불이 되자 "9분은 아직 길다"는 생각이 들었다. 이번에는 추측 대신 프로파일링을 했다. 병목은 특정 테스트가 아니라 모든 DB 테스트의 setUp에 깔린 두 가지였다.

• Argon2id 해시 111초(전체의 55%). 스위트 한 번에 password_hash()가 612회 불렸고, 운영 파라미터(64MB, 반복 4회)라 1회에 190ms였다. 비용 파라미터를 Config\Password로 분리하고 phpunit.dist.xml에서만 낮췄다(190ms → 0.66ms). 설정 기본값은 그대로라 운영 해시 강도는 바뀌지 않는다.
• TRUNCATE 53초. InnoDB의 TRUNCATE는 테이블스페이스를 다시 만드는 파일 조작이라 DELETE보다 훨씬 비싸다. 실측에서 TRUNCATE는 81초, DELETE 후 AUTO_INCREMENT 리셋은 81초, DELETE만은 28초였다. DELETE로 바꾸고, "첫 행의 id는 1"이라고 가정한 테스트 하나를 고쳤다.

3분 22초가 28초가 됐다. 처음 시작점이던 1시간 이상에서는 100배 넘게 줄어든 셈이다.

14. 하루를 돌아보며: 표로 정리

15. 남은 교훈

1. "한 줄 수정 → 재실행"은 CI에서 가장 비싼 루프다. 한 번에 510분이 든다. #134#137 네 번의 추측이 그 값을 치렀고, #138은 로컬 재현으로 한 번에 끝났다. 가설이 두 번 틀리면 CI를 그만 돌리고 로컬에서 재현한다.
2. 초록불을 의심한다. 예전 CI는 초록불이었지만 엉뚱한 DB에 붙어 있었다. "CI가 아무것도 전달받지 못했으면 실패"하는 가드 테스트가 이날 가장 오래 남을 산출물이다.
3. 환경이 바뀌면 숨어 있던 가정이 드러난다. DB 접속(#138)과 Redis 포트(#143)는 같은 병이었다. 하나를 고치고 나면 "같은 패턴이 또 어디 있나"를 바로 찾는다.
4. 진짜 병목은 처음 의심한 곳에 없었다. MySQL이 죽었다고 생각했지만 느려서 타임아웃이 났을 뿐이다. 추측하기 전에 계측부터 하는 쪽이 결국 빨랐다.
5. 로컬에서 composer check를 돌리고 올린다. #139 같은 PSR-12 한 줄이 PR 번호를 하나 낭비한다.
6. CI가 dev → main에서만 도는 구조는 검증이 늦다. 러너 이전 같은 CI 변경은 로컬 docker로 미리 재현해 두면 이 하루의 절반을 줄일 수 있었다.

에필로그: 한 달 뒤 같은 길을 한 번 더

10월에 러너를 docker 라벨의 컨테이너형으로 다시 옮기면서 같은 종류의 실패가 반복됐다(#147~#150). 이번에는 러너 자체가 컨테이너라 호스트에 게시한 포트(-p)가 127.0.0.1로 닿지 않았다. 실행별 도커 네트워크를 만들고 컨테이너 이름으로 접속하는 방식으로 풀었고, 테스트 DB 컨테이너는 --tmpfs와 durability 완화 옵션으로 체크포인트 스톨을 없앴다. 그날 정리한 내용은 CLAUDE.md의 "CI 러너 주의사항" 항목에 남겨 두었다. 일지를 남기는 이유다. 같은 실수를 두 번째에는 PR 한 개로 끝내려고.