SSE 연결 끊김 트러블슈팅: HttpLoggingFilter와 Content-Length 충돌

초기 SSE 연결은 확인할 수 있었는데 이후 하트비트 혹은 이벤트 값이 전송이 안 되는 문제가 발생했습니다.

 

결론부터 말하자면, Filter에서 로그를 남기고 있었고, Filter가 SSE 연결을 강제로 끊어버리고 있었습니다.

---

 

위와 같이 개발자 도구를 통해서 SSE 연결이 잘 된 것을 확인할 수 있었는데요, 추가적인 하트비트 응답이 오지 않는 상황이었습니다. 

세부적인 로깅을 통해 하트비트를 수행하는 스케줄러는 잘 동작하는걸 확인할 수 있었는데요, 이상하게 응답이 오지 않았습니다. 

 

원인은 Filter를 통해 모든 Request, Response에 대해 로깅을 남기고 있어서였습니다.

@Override
protected void doFilterInternal(
        final HttpServletRequest request,
        final HttpServletResponse response,
        final FilterChain filterChain
) throws ServletException, IOException {

    final String requestURI = request.getRequestURI();
    if (isExcluded(requestURI)) {
        filterChain.doFilter(request, response);
        return;
    }

    final ContentCachingRequestWrapper cacheRequest = new ContentCachingRequestWrapper(request);
    final ContentCachingResponseWrapper cacheResponse = new ContentCachingResponseWrapper(response);

 

과거 제가 작성한 Filter 코드 중 일부분입니다.

 

HTTP의 모든 요청/응답 로깅을 위해 HttpServletRequest와 HttpSerlvetResposne를 ContentCachingWrapper로 래핑 해서 사용하고 있었습니다. HttpServletRequest, response는 기본적으로 한 번 읽으면 사라지는 스트림 형식으로 되어있습니다. 래핑을 하지 않으면, 로그에서 해당 요청/응답을 소모해 DispatcherServlet으로 요청이 전송되지 않기에 ContentCachingWrapper를 통해 한 번 래핑을 했습니다.

 

바로 이 과정이 SSE 요청을 처리하는 과정에서 문제가 되었는데요,

Filter -> Controller로 요청이 갈 때 HttpServletResponse 객체가 가는 게 아니라, ContentCachingResponseWrapper가 response로 넘어가게 됩니다. 이후에 controller가 SseEmitter를 반환하고 메서드가 종료되면 Tomcat이 아닌, Filter로 돌아옵니다.

 

(이해를 돕기 위한 Controller 코드)

@RestController
@RequiredArgsConstructor
public class SseController implements SseApi {

    private final SseService sseService;

    @Override
    public SseEmitter subscribe(final UUID organizationUuid, final GuestInfo guestInfo) {
        return sseService.createEmitter(
                organizationUuid,
                guestInfo.guestUuid().toString(),
                ConnectionType.GUEST
        );
    }
}

 

 

이때, Filter는 로깅을 위해 Wrapper에 캐싱된 데이터(초기 연결 메시지)의 크기를 확인하고, 이를 전체 응답 크기로 착각하여 응답 헤더에 Content-Length를 강제로 명시해 버립니다. Client는 Content-Type이 text/event-stream임에도 불구하고, 헤더에 명시된 Content-Length 크기만큼만 데이터를 수신한 뒤 통신이 완료되었다고 판단하여 연결을 스스로 끊어버리는 현상이 발생한 것이죠.

 

그림을 통해 자세히 이해해 봅시다.

 

정상적인 구조의 응답 흐름입니다.

 

오류가 발생한 현재 구조의 응답 흐름입니다.

 

---

해결방안

매우 간단합니다. 그냥 Filter에 Exclude URI에 SSE API 추가해 주면 끝입니다...

private static final List<String> EXCLUDE_URI = List.of(
        "/actuator/**",
        "/swagger-ui/**",
        "/api-docs",
        "/sse/**"
);

 

진짜 에러 찾느라 엄청 고생했네요... 

 

기록 겸 팀원들에게 공유하려고 글을 적었는데, 같은 문제가 발생하신 분이 있다면, 이 글을 통해 빠르게 해결하셨으면 좋겠네요.