컨트롤러에서 예외 발생 시 작동 원리

웹 브라우저에서 서버가 요청을 받고 응답을 보내는 과정 중 컨트롤러에서 예외가 발생했다. 이러한 경우 서블릿에서 예외가 어떻게 처리되는지 알아보자.

1. 클라이언트가 서버에 요청 -> WAS(여기까지 전파) -> 필터(REQUSET) -> 서블릿 -> 인터셉터 -> 컨트롤러(예외 발생)
2. WAS(여기까지 전파) <- 필터 <- 서블릿 <- 인터셉터 <- 컨트롤러
3. WAS `/error-page/500` 다시 요청 -> 필터 -> 서블릿 -> 인터셉터 -> 컨트롤러(/error- page/500) -> View (ERROR)

Filter 코드를 보자.

package hello.exception.filter;

import lombok.extern.slf4j.Slf4j;

import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import java.io.IOException;
import java.util.UUID;

@Slf4j
public class LogFilter implements Filter {

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
        log.info("log filter init");
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        String requestURI = httpRequest.getRequestURI();

        String uuid = UUID.randomUUID().toString();

        try {
            log.info("REQUEST  [{}][{}][{}]", uuid, request.getDispatcherType(), requestURI);
            chain.doFilter(request, response);
        } catch (Exception e) {
            log.info("EXCEPTION {}", e.getMessage());
            throw e;
        } finally {
            log.info("RESPONSE [{}][{}][{}]", uuid, request.getDispatcherType(), requestURI);
        }
    }

    @Override
    public void destroy() {
        log.info("log filter destroy");
    }
}

이 코드를 보면, 마치 필터의 try-catch 문에서 예외를 처리하는 것 처럼 보인다. 하지만, 예외가 발생한 상황을 로그를 찍어 확인해보면 다음과 같다.

2022-08-19 13:13:09.472  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : REQUEST [58508771-671b-4066-aee6-8d5ea0bfbca2][REQUEST][/error-ex]
2022-08-19 13:13:09.475  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : error info=Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!
2022-08-19 13:13:09.475  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : RESPONSE [58508771-671b-4066-aee6-8d5ea0bfbca2][REQUEST][/error-ex]
2022-08-19 13:13:09.477 ERROR 6064 --- [nio-8080-exec-8] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!] with root cause

java.lang.RuntimeException: 예외 발생!
	at hello.exception.servlet.ServletExController.errorEx(ServletExController.java:16) ~[main/:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:655) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:764) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at hello.exception.filter.LogFilter.doFilter(LogFilter.java:25) ~[main/:na]


2022-08-19 13:13:09.478  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : REQUEST [48f2065c-4ed1-47ae-9fc5-0235fb09b113][ERROR][/error-page/500]
2022-08-19 13:13:09.479  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : errorPage 500
2022-08-19 13:13:09.480  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_EXCEPTION: {}

java.lang.RuntimeException: 예외 발생!
	at hello.exception.servlet.ServletExController.errorEx(ServletExController.java:16) ~[main/:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:655) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:764) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at hello.exception.filter.LogFilter.doFilter(LogFilter.java:25) ~[main/:na]

2022-08-19 13:13:09.480  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_EXCEPTION_TYPE: class java.lang.RuntimeException
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_MESSAGE: Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_REQUEST_URI: /error-ex
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_SERVLET_NAME: dispatcherServlet
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_STATUS_CODE: 500
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : dispatchType=ERROR
2022-08-19 13:13:09.482  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : RESPONSE [48f2065c-4ed1-47ae-9fc5-0235fb09b113][ERROR][/error-page/500]

로그를 하나씩 살펴보자.

1.

2022-08-19 13:13:09.472  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : REQUEST [58508771-671b-4066-aee6-8d5ea0bfbca2][REQUEST][/error-ex]

• 필터의 doFilter()에서 try 구문의 로그가 찍혔다. 중요한 것은 여기서 catch 구문으로 넘어가는 것이 아니라, chain.doFilter()가 호출되어 try 구문에서 서블릿, 인터셉터, 컨트롤러가 호출이 된다. 따라서, 컨트롤러에서 예외가 발생한다.

2.

2022-08-19 13:13:09.475  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : error info=Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!

• 컨트롤러에서 예외가 발생하면 다시 역순으로 WAS까지 예외가 전달되야하므로 다시 컨트롤러부터 인터셉터, 서블릿, 필터 순으로 예외가 전달된다.
• 과정 중 필터에서 예외가 전달되어 이 때는 catch문으로 가서 로그를 찍고 예외를 던진다. (throw e;)

3.

2022-08-19 13:13:09.475  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : RESPONSE [58508771-671b-4066-aee6-8d5ea0bfbca2][REQUEST][/error-ex]

• 필터의 catch 구문을 거쳐도 finallly가 호출되므로 해당 부분의 로그가 찍혔다.

4.

2022-08-19 13:13:09.477 ERROR 6064 --- [nio-8080-exec-8] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!] with root cause

java.lang.RuntimeException: 예외 발생!
	at hello.exception.servlet.ServletExController.errorEx(ServletExController.java:16) ~[main/:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:655) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:764) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at hello.exception.filter.LogFilter.doFilter(LogFilter.java:25) ~[main/:na]

• WAS까지 전달되어 로그를 찍어주고 이제 해당 예외에 맞는 오류 페이지를 다시 요청한다. (물론 이러한 과정은 클라이언트는 아예 모른다.)
• WAS는 오류 페이지를 단순히 다시 요청만 하는 것이 아니라, 오류 정보를 request 의 attribute 에 추가해서 넘겨준다.

5.

2022-08-19 13:13:09.478  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : REQUEST [48f2065c-4ed1-47ae-9fc5-0235fb09b113][ERROR][/error-page/500]
2022-08-19 13:13:09.479  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : errorPage 500
2022-08-19 13:13:09.480  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_EXCEPTION: {}

java.lang.RuntimeException: 예외 발생!
	at hello.exception.servlet.ServletExController.errorEx(ServletExController.java:16) ~[main/:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:655) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:764) ~[tomcat-embed-core-9.0.65.jar:4.0.FR]
	at hello.exception.filter.LogFilter.doFilter(LogFilter.java:25) ~[main/:na]

2022-08-19 13:13:09.480  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_EXCEPTION_TYPE: class java.lang.RuntimeException
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_MESSAGE: Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_REQUEST_URI: /error-ex
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_SERVLET_NAME: dispatcherServlet
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : ERROR_STATUS_CODE: 500
2022-08-19 13:13:09.481  INFO 6064 --- [nio-8080-exec-8] h.exception.servlet.ErrorPageController  : dispatchType=ERROR
2022-08-19 13:13:09.482  INFO 6064 --- [nio-8080-exec-8] hello.exception.filter.LogFilter         : RESPONSE [48f2065c-4ed1-47ae-9fc5-0235fb09b113][ERROR][/error-page/500]

• 1 ~ 4 과정을 다시 반복한다. 에러 페이지(/error-page/500
  ) 컨트롤러를 호출하는 과정이며 이 컨트롤러에는 request에 대한 다양한 정보를 로그로 출력하는 메소드가 정의되어 있다.
• 오류 페이지 컨트롤러를 호출하여 request에 대한 다양한 로그가 찍힌다.

참고) 오류페이지 컨트롤러에서 정의된 request의 다양한 정보를 로그로 출력하는 메소드

private void printErrorInfo(HttpServletRequest request) {
    log.info("ERROR_EXCEPTION: {}", request.getAttribute(ERROR_EXCEPTION));
    log.info("ERROR_EXCEPTION_TYPE: {}", request.getAttribute(ERROR_EXCEPTION_TYPE));
    log.info("ERROR_MESSAGE: {}", request.getAttribute(ERROR_MESSAGE));
    log.info("ERROR_REQUEST_URI: {}", request.getAttribute(ERROR_REQUEST_URI));
    log.info("ERROR_SERVLET_NAME: {}", request.getAttribute(ERROR_SERVLET_NAME));
    log.info("ERROR_STATUS_CODE: {}", request.getAttribute(ERROR_STATUS_CODE));
    log.info("dispatchType: {}", request.getDispatcherType());
}

물론, 이렇게 필터가 두 번 호출되는 것은 request.DispatchType을 설정하여 오류 상황에선 호출되지 않도록 할 수 있다.

이러한 상황은 컨트롤러에서 예외가 발생했을 때 경우이다. 처음에 코드를 보았을 때 필터에서 예외가 터지는 줄 알았지만 chain.doFilter() 메소드를 통해 컨트롤러까지 요청이 전달되면서 컨트롤러에서 예외가 발생한다는 것이 핵심이다. 꼭 알아두자.