NGINX ctx와 error_page에 관한 코어 덤프 이야기
Wei Liu
September 16, 2022
프로덕션 환경에서 코어 덤프는 엔지니어들에게 공포의 대상입니다. 특히 한밤중에 크래시가 발생하면 더욱 그렇습니다. 저도 10여 년 전에 직접 경험한 적이 있습니다. 밤에만 나타나는 이 "유령" 버그를 찾기 위해, 팀 전체가 오후에 집에 가서 잠을 자고, 자정에 회사로 돌아와 크래시를 기다리며 각 서비스를 하나씩 확인했던 기억이 납니다. 어두운 밤, 몇 개의 워크스테이션만 불이 켜진 사무실에서 데이터와 로그를 보며 모니터를 지켜보던 그 강렬하고 흥미로운 경험을 떠올리면 아직도 생생합니다. 우리는 버그를 찾아 해결하기까지 3일 밤을 꼬박 새웠고, 그 경험은 잊을 수 없었습니다.
그런데 우리가 다시 한 번 이런 경험을 하게 될 줄은 몰랐습니다. 이번에는 우리 서비스가 아니라 클라이언트의 온라인 서비스에서 코어 덤프가 발생했습니다. 이는 우리가 통제할 수 있는 환경보다 훨씬 더 어려운 상황이었습니다:
- 오류는 사용자의 프로덕션 환경에서만 발생했으며, 사용자는 자체 스테이징 환경과 테스트 환경에서도 오류를 재현할 수 없었습니다.
- 사용자는 오픈 소스 Apache APISIX 위에 커스텀 코드를 추가했는데, 별도의 NDA를 체결하기 전까지는 이 코드를 볼 수 없었습니다.
- 디버그 로그를 추가할 수 없었습니다.
- 오류는 오전 3시에만 발생했기 때문에, 클라이언트의 추가 리소스가 즉시 필요했습니다.
요약하자면, 이 문제는 재현할 수 없고, 완전한 소스 코드도 없으며, 테스트할 환경도 없는 상황이었습니다. 그러나 우리는 오류를 찾아내고, 재현 방법을 찾아내고, 결국 수정 방법을 제공해야 했습니다. 이 과정에서 많은 도전을 겪었고, 그로부터 많은 것을 배웠습니다. 여기서는 디버깅 과정에서 마주친 몇 가지 흥미로운 점을 공유합니다. 이 글이 NGINX와 APISIX를 디버깅하는 사람들에게 도움이 되길 바랍니다.
문제 설명
사용자가 APISIX를 2.4.1 버전에서 2.13.1 버전으로 업그레이드한 후, 주기적으로 코어 덤프가 발생했습니다. 오류 메시지는 다음과 같습니다:
코어 덤프 메시지에서 세그멘테이션 폴트가 lua-var-nginx-module에서 발생한 것을 확인할 수 있었습니다. 그리고 메모리의 해당 데이터(일부)는 다음과 같습니다:
#0 0x00000000005714d4 in ngx_http_lua_var_ffi_scheme (r=0x570d700, scheme=0x7fd2c241a760)
at /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c:152
152 /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c: No such file or directory.
(gdb) print *r
$1 = {signature = 0, connection = 0x0, ctx = 0x15, main_conf = 0x5adf690, srv_conf = 0x0, loc_conf = 0x0, read_event_handler = 0xe, write_event_handler = 0x5adf697,
cache = 0x2, upstream = 0x589c15, upstream_states = 0x0, pool = 0x0, header_in = 0xffffffffffffffff}
메모리의 데이터에 문제가 있음을 확인할 수 있습니다.
분석 전 몇 가지 생각
세그멘테이션 폴트는 일반적으로 두 가지 시나리오에서 발생합니다:
- 메모리에서 유효하지 않은 주소를 읽거나 쓰는 경우, 예를 들어 배열 인덱스를 벗어난 접근을 하면 즉시 세그멘테이션 폴트가 발생합니다.
- 유효하지 않은 쓰기를 수행하지만 유효한 주소를 수정하는 경우, 즉시 세그멘테이션 폴트가 발생하지 않습니다. 프로그램 실행 중에 잘못된 주소의 데이터에 접근하려고 할 때 세그멘테이션 폴트가 발생합니다. 예를 들어, 포인터의 값이 잘못 수정된 경우, 나중에 이 포인터에 접근할 때 세그멘테이션 폴트가 발생할 수 있습니다.
첫 번째 시나리오의 경우, 호출 스택을 확인하면 문제를 쉽게 찾을 수 있습니다.
두 번째 시나리오의 경우, 오류가 처음 발생한 위치가 명확하지 않기 때문에, 오류를 발생시킨 코드와 세그멘테이션 폴트를 유발한 코드가 같은 위치에 있지 않을 수 있으며, 완전히 관련이 없을 수도 있어 문제를 찾기 어렵습니다. 우리는 충돌과 관련된 더 많은 컨텍스트 정보를 수집해야 했습니다. 예를 들어:
- 현재 APISIX의 구성 세부 사항.
- 현재 요청의 처리 단계.
- 현재 요청의 세부 사항.
- 동시 연결 수.
- 오류 로그.
이 정보를 통해 코드를 검토하고 문제를 재현할 방법을 찾아 버그를 찾으려고 했습니다.
분석
1. 오류의 컨텍스트 확인
신중한 분석 결과, 오류는 일반적으로 오전 3시에서 4시 사이에 발생하며, 다음과 같은 코어 덤프 오류 메시지가 나타났습니다:
결국, 우리는 오류 로그가 사용자 작업과 관련이 있음을 깨달았습니다. 특정 이유로 이 시간에 모든 업스트림 메시지가 지워졌습니다. 그래서 우리는 문제가 업스트림 클리어/리셋 작업과 관련이 있으며, 오류 반환 후 예외 분기에 진입하여 코어 덤프가 발생했을 가능성을 의심했습니다.
2. Lua의 호출 스택 얻기
GDB는 Lua의 호출 스택을 추적할 수 없기 때문에, 우리는 오류를 발생시킨 호출을 찾을 수 없었습니다. 따라서 우리가 가장 먼저 해야 할 일은 Lua의 호출 스택을 얻는 것이었습니다. 우리는 두 가지 방법으로 호출 스택을 얻을 수 있었습니다:
- lua-var-nginx-module 라이브러리에 호출 스택을 출력하는 코드를 추가합니다
(print(debug.traceback(...)). 단점은 많은 오류 로그를 생성하여 프로덕션 환경에 부정적인 영향을 미칠 수 있다는 것입니다. - API7.ai가 유지 관리하는 openresty-gdb-utils를 사용합니다. 이 툴킷은 GDB의 DSL과 파이썬 확장을 사용하여 GDB의 Lua 호출 스택 분석 능력을 향상시킵니다. 컴파일 시 디버그 심볼을 켜야 합니다. APISIX에는 기본적으로 포함되어 있습니다.
그런 다음, 우리는 다음과 같은 호출 스택을 얻었습니다.
Lua와 C의 호출 스택을 결합하여, 우리는 사용자가 Prometheus 플러그인에서 ngx.ctx.api_ctx.var.scheme를 호출했기 때문에 코어 덤프가 발생했음을 확인했습니다. 그러나 충돌의 원인은 여전히 명확하지 않았고, 더 분석이 필요했습니다.
3. 캐시가 문제를 일으킴
ngx.ctx.api_ctx.var에서 변수에 접근할 때 위에서 설명한 lua-var-nginx-module에서 호출이 실행되었습니다. 효율성을 높이기 위해 현재 요청을 캐시했습니다. 우리는 요청 본문의 값에 예외가 있을 때 오류가 발생했음을 기억했기 때문에, 캐시된 요청의 유효성도 의심스러웠습니다. 이 생각을 검증하기 위해, 프로그램이 캐시된 메모리를 사용하지 않고 매번 요청을 다시 가져오도록 수정했습니다.
else
--val = get_var(key, t._request)
val = get_var(key, nil) <============ t._request change to nil
end
사용자는 이 수정된 버전으로 하룻밤 동안 테스트했고, 오류가 다시 발생하지 않았습니다. 우리는 요청 본문에 문제가 있음을 확인했습니다.
4. ngx.ctx의 오류
캐시된 요청 본문은 ngx.ctx에 저장되었고, ngx.ctx를 수정하는 유일한 곳은 apisix/init.lua였습니다.
function _M.http_header_filter_phase()
if ngx_var.ctx_ref ~= '' then
-- prevent for the table leak
local stash_ctx = fetch_ctx()
-- internal redirect, so we should apply the ctx
if ngx_var.from_error_page == "true" then
ngx.ctx = stash_ctx <================= HERE
end
end
core.response.set_header("Server", ver_header)
local up_status = get_var("upstream_status")
if up_status then
set_resp_upstream_status(up_status)
end
왜 여기서 ngx.ctx를 복구해야 했을까요? ngx.ctx는 Lua 레지스트리에 저장되며, 레지스트리 인덱스를 통해 해당 ngx.ctx를 찾을 수 있습니다. 그리고 이 인덱스는 NGINX 요청 구조체의 ctx 멤버에 저장됩니다. 내부 리디렉션이 발생할 때마다 NGINX는 ctx를 지우므로 인덱스를 찾을 수 없습니다.
이 문제를 해결하기 위해 APISIX는 테이블을 생성했습니다. 이 테이블은 리디렉션 전에 현재 ngx.ctx를 저장하고, ngx.var를 사용하여 이 테이블에서 ngx.ctx의 인덱스를 기록했습니다. 복구가 필요할 때마다 테이블에서 직접 ngx.ctx를 가져올 수 있었습니다.
위 그림의 코드는 사용자가 error_page 지시어를 구성하고 내부 리디렉션 후 오류가 발생했을 때만 트리거되었습니다.
그리고 우리는 사용자가 버전 업그레이드 후 error_page 지시어를 켰다는 것을 정확히 알고 있었고, 위에서 설명한 업스트림 변경으로 인한 오류와 결합되었습니다. 모든 것이 연결되어 있는 것 같았습니다. 오류 처리 과정에서 ngx.ctx가 버그를 일으킨 것일까요?
5. ngx.ctx에 버그가 있는 이유
이 질문을 가지고, 우리는 ngx.ctx와 관련된 백업 코드를 확인했고, 더 이상한 문제를 발견했습니다. set_upstream이 실패한 후, ngx.ctx 복구 단계를 거치지 않았습니다. 왜냐하면 조기에 종료되었기 때문에 ngx.ctx를 백업하지 않았고, 복구 과정도 거치지 않았습니다.
이것은 분명히 버그였습니다! ngx.ctx는 리디렉션 후 복구되어야 합니다. 그리고 이 과정에서 ngx.ctx가 어떻게 복구되었는지, 처음에 ngx.ctx가 어떻게 잘못되었는지가 궁금했습니다. 이제 너무 많은 불확실성이 있었고, 더 많은 데이터를 수집해야 했습니다.
논의 후, 우리는 프로덕션에 두 번째 로그를 추가했고, 내부 리디렉션 후 오류가 발생했을 때 ngx.ctx가 복구 과정을 거치지 않고 바로 코어 덤프를 일으킨다는 것을 발견했습니다!
이것은 혼란스러운 현상이었습니다. 왜냐하면 리디렉션 후 ngx.ctx가 복구되지 않았다면 ngx.ctx는 비어 있거나 null이어야 합니다. 그리고 빈 값을 확인하는 코드가 있었기 때문에 플러그인에서 코어 덤프 코드를 트리거해서는 안 됩니다.
local function common_phase(phase_name)
local api_ctx = ngx.ctx.api_ctx
if not api_ctx then <============ HERE
return
end
plugin.run_global_rules(api_ctx, api_ctx.global_rules, phase_name)
그렇다면 이 error_page 내부 리디렉션이 ngx.ctx에 문제를 일으킨 것일까요?
6. 초기 결론
분석과 확인을 통해 우리는 오류 과정에 대한 기본적인 이해를 얻었습니다.
set_upstream이 실패하고 error_page의 오류 처리 단계로 리디렉션되었으며, 예상대로 비어 있어야 할 ngx.ctx에 예상치 못한 값이 있었습니다. 그리고 APISIX의 버그로 인해 리디렉션 전에 ngx.ctx를 복구하지 않았기 때문에, ngx.ctx에 접근할 때 더러운 데이터가 있어 코어 덤프가 발생했습니다. 이 문제를 해결하기 위해 우리는 리디렉션 후 ngx.ctx를 복구하기만 하면 되었습니다. 이 커밋의 상세 구현은 글 마지막에 참조용으로 제공됩니다.
버그에 대한 수정을 제공했지만, 우리는 여전히 버그의 완전한 논리를 이해하지 못했습니다. 사용자가 ngx.ctx의 로직을 수정하지 않았기 때문에 오픈 소스 버전에서도 재현할 수 있어야 했습니다. 사용자의 프로덕션 환경과 배포 과정에 계속 영향을 미치지 않기 위해, 우리는 근본 원인을 계속 조사하기로 결정했습니다.
7. 성공적인 재현
우리가 알고 있는 것만으로는 문제를 재현할 수 없었습니다. 분석 후, 우리는 다음 두 가지를 확인하기로 결정했습니다:
- 내부 리디렉션에 특별한 처리 분기가 있는가?
- ngx.ctx에 특별한 처리 분기가 있는가?
첫 번째 점에 대해, NGINX의 각 필터 모듈 처리 중에 요청 본문의 ctx 멤버에 영향을 미칠 수 있는 예외 분기가 있을 수 있습니다. 우리는 사용자의 NGINX에 컴파일된 모듈을 확인했지만, 유사한 문제를 찾지 못했습니다.
두 번째 점에 대해, 조사 결과 SSL 핸드셰이크 중에 ngx.ctx가 재사용으로 인해 문제가 발생한다는 것을 발견했습니다. HTTP 단계에서 ngx.ctx를 얻을 수 없으면 SSL 단계에서 얻으려고 시도합니다. SSL 단계에는 자체 ngx.ctx가 있으며, 이로 인해 ngx.ctx에 문제가 발생할 수 있습니다.
이러한 발견을 바탕으로, 우리는 다음과 같은 조건을 설계하고 문제를 성공적으로 재현할 수 있었습니다:
- 사용자와 동일한 APISIX 버전
- SSL 인증서 켜기
- 내부 오류를 발생시켜 error_page 트리거(예: 업스트림이 없을 때 업스트림 요청)
- 장기 연결
- Prometheus 플러그인(사용자의 경우 플러그인에서 코어 덤프 발생)
우리는 마침내 흙으로 벽돌을 만들었습니다. 추측과 검증을 통해 이 버그의 완전한 과정을 알아냈습니다. 완전한 재현이 가능해지면 문제를 해결하는 것은 더 이상 어렵지 않으며, 최종 과정은 여기서 자세히 설명하지 않겠습니다. 정확히 재현할 수 있는 문제에 대한 경험이 많으리라 믿습니다.
요약
이 문제의 근본 원인: error_page에 진입한 후 ngx.ctx가 복구되지 않아 장기 연결의 모든 요청이 SSL 단계에서 동일한 ngx.ctx를 재사용하게 됩니다. 결국 ngx.ctx에 더러운 데이터가 있어 코어 덤프가 발생했습니다.
후속 조치로, 우리는 이 문제에 대한 해결책을 제안했습니다: 내부 리디렉션 후 ngx.ctx가 정상적으로 복구되도록 보장합니다. 구체적인 PR을 참조하세요.
APISIX가 error_page와 같은 내부 리디렉션 기능을 사용한다면, 최신 버전으로 업그레이드하는 것을 권장합니다.
프로그래밍과 디버깅은 과학적으로 엄격한 작업이며, 모호함이 없어야 합니다. 문제를 해결하기 위해서는 정보를 수집하고, 모든 잠재적인 단서를 추적하며, 호출 스택을 분석한 후 오류를 재현할 컨텍스트를 파악해야 합니다. 마지막으로 문제를 해결합니다.