BLOG기술
당신의 로깅 필터는 안녕하신가요
ContentCachingResponseWrapper가 빈 응답을 내려보냈다면, 비동기 요청을 의심하세요
안녕하세요, 디라이브 개발팀 정종길입니다.
요청과 응답을 로그로 남기는 필터는 운영을 해 본 사람이라면 한 번은 만들어 봤을 코드이고, 비즈니스 로직과 무관한 횡단 관심사라서 가볍게 넣고 가볍게 잊게 됩니다. 저도 에러가 났을 때 요청과 응답 내용을 남기려고 로깅 필터에 캐싱 래퍼를 한 겹 씌웠는데, 그 변경이 멀쩡히 돌던 롱 폴링 API를 깨뜨렸다는 사실을 알아내는 데 이틀이 걸렸습니다.
그때 무엇을 봤고 어디서 헤맸고 어떻게 고쳤는지를 적어 봤는데요. Spring Boot 3.5(Spring Framework 6.2)에서 ContentCachingResponseWrapper로 응답 바디를 기록하는 필터와 DeferredResult 기반의 비동기 API가 만났을 때 어떤 일이 생기는지에 대한 이야기입니다. 서블릿 필터 체인과 비동기 디스패치가 어떻게 얽히는지를 사례 하나로 보고 싶은 분에게도 도움이 되면 좋겠습니다.
서버는 주는데 앱은 받지 못했습니다
QA 채널에 운전점수가 서버에서는 나가는데 앱에서는 안 바뀐다는 보고가 올라왔습니다. 운전점수는 운전자 앱이 롱 폴링으로 받아 가는 값이라서, 앱이 요청을 걸어 두면 서버는 새 점수가 계산될 때까지 응답을 보류하고 있다가 값이 생기면 그때 내려주는 구조였습니다.
처음에는 클라이언트 쪽 문제라고 생각했습니다. 서버 로그에는 점수 계산도 응답 객체 생성도 정상으로 찍혀 있었기 때문인데, 테스트 폰에서도 같은 현상이 재현됐고 서버에서 직접 호출해 보니 상태 코드는 200인데 바디가 비어 있고 Content-Length는 0이었습니다. 서버는 정상 응답을 보냈다고 하는데 페이로드는 없는 상태였습니다.
빈 바디를 보면 먼저 직렬화를 의심하게 됩니다. 하지만 Jackson이 직렬화에 실패했다면 상태 코드가 200일 리 없고 예외 로그도 남았어야 했는데, 둘 다 아니었습니다. 다음으로 의심한 것은 타임아웃이었습니다. 롱 폴링은 DeferredResult로 구현돼 있었고, 새 점수가 없는 채로 타임아웃이 나면 onTimeout()에서 빈 목록을 담아 200으로 응답하게 되어 있었으니 혹시 그 응답이 나가는 것은 아닐까 생각했습니다. 그런데 그랬다면 바디에 빈 배열이라도 있어야 했고, 로그를 더 찍어 보니 setResult()는 타임아웃보다 훨씬 앞서 실제 점수로 호출되고 있었습니다. 결과는 세팅되는데 클라이언트에는 전달되지 않는 상황을 놓고 하루를 보냈습니다.
이쯤에서 질문을 바꿨습니다. 이 코드가 왜 안 되는지가 아니라 언제부터 안 됐는지를 보기로 하고 커밋 이력을 거슬러 올라갔는데, 2주 남짓 전에 에러 상황의 요청과 응답 내용을 남기려고 로깅 필터에 ContentCachingResponseWrapper를 씌운 커밋이 눈에 들어왔습니다. 운영 이슈를 추적하기 편하게 하려고 넣은 것이고 기능과는 아무 상관이 없다고 생각했던 변경이었는데, 그 래퍼를 빼 봤더니 롱 폴링이 살아났습니다.
필터는 응답의 일부입니다
로깅 필터는 흔히 보는 모양이었고, 요점만 남기면 이렇습니다.
public class LoggingFilter extends OncePerRequestFilter {
@Override
protected void doFilterInternal(HttpServletRequest req, HttpServletResponse res,
FilterChain chain) throws IOException, ServletException {
var wrapped = new ContentCachingResponseWrapper(res);
chain.doFilter(req, wrapped);
log.info("response: {}", new String(wrapped.getContentAsByteArray()));
wrapped.copyBodyToResponse(); // 캐시해 둔 바디를 실제 응답 스트림에 복사
}
}ContentCachingResponseWrapper는 컨트롤러가 응답 스트림에 쓴 바디를 가로채 내부 버퍼에 캐시하는 래퍼이고, chain.doFilter()는 필터 체인의 나머지와 DispatcherServlet을 실행하고 돌아오는 호출입니다. 그러니 doFilter()가 반환된 뒤 버퍼를 읽으면 로그를 남길 수 있고, copyBodyToResponse()로 원본 응답 스트림에 흘려보내면 클라이언트도 바디를 받습니다. 동기 요청에서는 doFilter()가 반환된 시점에 컨트롤러 실행과 응답 바디 직렬화가 모두 끝나 있기 때문에 이 순서가 맞습니다.
DeferredResult는 이 전제를 깨는 타입입니다. 서블릿 3.0의 비동기 처리 위에서 동작하는데, 컨트롤러가 빈 DeferredResult를 반환하면 Spring은 AsyncContext를 열어 요청을 비동기 모드로 전환하고 컨테이너 스레드를 풀에 반납합니다. 응답은 커밋되지 않은 채 열려 있다가, 나중에 워커 스레드가 setResult()를 호출하면 컨테이너가 같은 요청을 ASYNC 타입으로 다시 디스패치하고 그 두 번째 패스에서 결과가 직렬화되어 응답에 쓰입니다.
@GetMapping("/driving-score")
public DeferredResult<Score> score() {
var result = new DeferredResult<Score>(30_000L); // 30초 타임아웃
waiters.add(result); // 어딘가에 보관해 두고
return result; // 결과 없이 즉시 반환, 컨테이너 스레드 반납
}
// 몇 초 뒤, 점수를 계산한 워커 스레드에서
result.setResult(newScore); // 이 시점에 ASYNC 디스패치가 일어난다여기서 필터와 충돌이 생깁니다. 비동기 모드로 전환되면 chain.doFilter()는 결과를 기다리지 않고 첫 번째 패스에서 바로 반환됩니다. 그 시점의 캐시 버퍼는 비어 있으니 필터는 빈 로그를 남기고, copyBodyToResponse()도 복사할 것이 없어 그냥 지나갑니다. 문제는 그다음입니다. Spring은 비동기를 시작할 때 첫 번째 패스에서 받은 응답 객체, 즉 필터가 감싼 래퍼를 AsyncContext에 넘기기 때문에, 몇 초 뒤 setResult()로 ASYNC 디스패치가 일어나면 진짜 결과는 이 래퍼의 버퍼에 직렬화됩니다. 그런데 OncePerRequestFilter는 기본적으로 ASYNC 디스패치를 건너뛰니, 버퍼를 원본 응답으로 옮겨 줄 copyBodyToResponse()는 다시 호출되지 않고 요청은 바디가 버퍼에 갇힌 채로 완료됩니다. 그래서 클라이언트는 빈 200을 받게 되고, 서버 로그에 결과 객체가 정상으로 찍혔던 이유도 여기에 있습니다. 결과는 만들어졌지만 클라이언트로 가는 길목에서 멈춰 있었던 것입니다.
고치는 방법은 이 구조에서 나옵니다. 비동기 요청은 REQUEST 디스패치와 ASYNC 디스패치, 이렇게 필터 체인을 두 번 지나고 바디는 두 번째에만 채워집니다. 그래서 필터가 두 번째 패스에도 실행되게 하고, 로깅과 복사는 그 두 번째 패스에서만 하면 됩니다. Spring에 기본으로 들어 있는 ShallowEtagHeaderFilter도 ContentCachingResponseWrapper를 상속한 래퍼로 응답 바디를 캐시하는데, 비동기 요청을 정확히 이 방식으로 처리하고 있습니다. 같은 구조로 정리하면 이렇습니다.
public class LoggingFilter extends OncePerRequestFilter {
@Override
protected boolean shouldNotFilterAsyncDispatch() {
return false; // 기본값 true. ASYNC 디스패치에도 필터를 태운다
}
@Override
protected void doFilterInternal(HttpServletRequest req, HttpServletResponse res,
FilterChain chain) throws IOException, ServletException {
// ASYNC 패스의 응답 안에는 첫 패스에서 씌운 래퍼가 이미 들어 있다
HttpServletResponse toUse = isAsyncDispatch(req)
? res : new ContentCachingResponseWrapper(res);
chain.doFilter(req, toUse);
if (isAsyncStarted(req)) {
return; // REQUEST 패스. 바디는 ASYNC 패스에서 채워진다
}
var wrapped = WebUtils.getNativeResponse(toUse, ContentCachingResponseWrapper.class);
log.info("response: {}", new String(wrapped.getContentAsByteArray()));
wrapped.copyBodyToResponse();
}
}바뀐 것은 셋입니다. 첫째는 shouldNotFilterAsyncDispatch()를 false로 오버라이드한 것입니다. OncePerRequestFilter는 기본적으로 ASYNC 디스패치를 건너뛰기 때문에, 이것을 바꾸지 않으면 두 번째 패스에 필터가 아예 실행되지 않습니다. 둘째는 chain.doFilter() 뒤에서 isAsyncStarted()를 확인하는 것인데, 비동기가 시작됐다면 바디가 아직 없는 REQUEST 패스라는 뜻이라서 로깅도 복사도 하지 않고 반환합니다. 그러면 로깅과 복사는 바디가 채워진 ASYNC 패스에서 한 번만 일어납니다. 셋째는 ASYNC 패스에서 래퍼를 새로 씌우지 않는 것입니다. 이 패스의 응답 객체 안에는 첫 번째 패스에서 씌운 래퍼가 이미 들어 있어서, 여기에 래퍼를 또 씌우면 결과가 바깥 래퍼에서 안쪽 래퍼로 옮겨질 뿐 여전히 클라이언트에 닿지 않습니다. 그래서 응답은 그대로 넘기고, 복사할 때 WebUtils.getNativeResponse()로 감싼 층을 풀어 처음 씌운 래퍼를 찾아 씁니다.
당시에는 이보다 단순하게, REQUEST 패스에서는 래퍼를 아예 씌우지 않고 ASYNC 패스에서만 씌워 복사하는 식으로 급하게 고쳤습니다. 롱 폴링은 그것만으로 살아났지만 일반 동기 요청은 래퍼 없이 지나가게 됐고, 위 코드는 동기 요청과 비동기 요청을 같은 방식으로 기록할 수 있게 정리한 형태입니다.
배포하고 앱에서 점수가 갱신되는 것을 확인한 뒤, QA 채널에는 원인과 함께 사과를 올렸습니다.
기능과 무관한 코드는 없었습니다
로깅 필터는 비즈니스 로직을 한 줄도 건드리지 않았지만, 응답을 래핑하는 순간 그 필터는 응답 생명주기의 일부가 됐습니다. 필터나 인터셉터처럼 모든 요청을 가로지르는 코드는 그래서 기능 코드보다 더 넓은 전제를 놓고 짜야 하고, 동기 요청만 머릿속에 그리고 짜면 비동기 디스패치에서 깨집니다. 저는 이것을 알고 있다고 생각했는데 알고 있는 것과 필터를 짜는 순간 떠올리는 것은 다른 일이었고, 그래서 지금은 응답에 손대는 코드를 쓸 때 이 요청이 비동기 모드로 전환될 수 있는지를 먼저 묻습니다. 이 필터도 결국 두 달쯤 뒤 로깅 전략을 다시 정리하면서 응답 래퍼를 아예 걷어내고, 요청 ID와 접근 로그만 남기는 쪽으로 바뀌었습니다.
추적 순서에 대해서도 생각이 바뀌었습니다. 직렬화와 타임아웃을 차례로 의심하면서 코드 안에서 원인을 찾느라 하루를 썼는데, 최근 변경 목록을 먼저 봤으면 반나절이었을 것입니다. 멀쩡히 돌던 기능이 깨졌다면 원인은 대개 최근 변경 안에 있다는 것을 머리로는 알고 있어도 장애 앞에 서면 코드부터 열게 되는데, 그래서 이제는 왜 안 되는지보다 언제부터 안 됐는지를 먼저 묻기로 했습니다.
다만 이 두 가지를 알았어도 이 버그를 서버 쪽에서 먼저 알아채기는 어려웠을 것입니다. 예외도 경고도 없이 조용히 빈 200을 내려보냈기 때문에, 로그를 잘 남기려고 넣은 코드가 로그에 아무것도 남기지 않는 장애를 만든 셈이 됐습니다. 이것을 잡아 준 것은 모니터링이 아니라 값이 안 바뀐다고 말해 준 사람이었고, 서버가 200을 돌려줬다는 것과 사용자가 원하는 값을 받았다는 것은 다른 일이라는 점을 그때 알았습니다.
마치며
비동기 요청은 필터 체인을 두 번 지납니다. 이 한 문장을 알고 있었다면 필터를 짜는 순간 isAsyncStarted()를 떠올렸을 것이고, 이것은 ContentCachingResponseWrapper만의 문제가 아니라 응답을 래핑하거나 커밋 시점에 관여하는 필터와 인터셉터 전부에 있는 함정입니다. 그래서 저는 서블릿 스택에서 DeferredResult나 Callable, SSE처럼 비동기 디스패치를 타는 엔드포인트가 하나라도 있다면 로깅 필터를 한 번 열어 보셨으면 합니다.
당신의 로깅 필터는 안녕하신가요. 저는 한 번 아니었습니다.
비슷한 경험이 있거나 다른 방식으로 푸신 분이 있다면 이야기 나눠 보고 싶습니다. 감사합니다.