서블릿 예외 처리 로그 분석

필터를 이용하여 서블릿에서 예외 처리를 하는 과정에서 출력되는 로그를 상세히 분석해 보고자 한다.

 

서블릿에서 예외 처리를 하는 과정의 흐름은 다음과 같다.

1. WAS(여기까지 전파) ← 필터 ← 서블릿 ← 인터셉터 ← 컨트롤러(예외발생)
2. WAS /error-page/500 다시 요청 → 필터 → 서블릿 → 인터셉터 → 컨트롤러(/error-page/500) → View

이를 기반으로 코드를 작성하고, 이를 수행하는 과정에서 출력되는 로그를 단계적으로 살펴볼 예정이다.

 

예외 처리를 위해 필요한 클래스

ServletExController - 클라이언트에 의한 요청 처리 컨트롤러

package hello.exception.servlet;

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.GetMapping;

import javax.servlet.http.HttpServletResponse;
import java.io.IOException;

@Slf4j
@Controller
public class ServletExController {

    @GetMapping("/error-ex")
    public void errorEx() {
        throw new RuntimeException("예외 발생!");
    }

    @GetMapping("/error-404")
    public void error404(HttpServletResponse response) throws IOException {
        response.sendError(404, "404 오류!");
    }

    @GetMapping("/error-500")
    public void error500(HttpServletResponse response) throws IOException {
        response.sendError(500);
    }

}

에러 처리를 테스트하기 위한 컨트롤러이다.

 

WebServerCustomizer - 서블릿 오류 페이지 등록

package hello.exception.servlet;

import org.springframework.boot.web.server.ConfigurableWebServerFactory;
import org.springframework.boot.web.server.ErrorPage;
import org.springframework.boot.web.server.WebServerFactoryCustomizer;
import org.springframework.http.HttpStatus;
import org.springframework.stereotype.Component;

@Component
public class WebServerCustomizer implements WebServerFactoryCustomizer<ConfigurableWebServerFactory> {

    @Override
    public void customize(ConfigurableWebServerFactory factory) {
        // error
        ErrorPage errorPage404 = new ErrorPage(HttpStatus.NOT_FOUND, "/error-page/404");
        ErrorPage errorPage500 = new ErrorPage(HttpStatus.INTERNAL_SERVER_ERROR, "/error-page/500");

        // exception
        ErrorPage errorPageEx = new ErrorPage(RuntimeException.class, "/error-page/500");

        factory.addErrorPages(errorPage404, errorPage500, errorPageEx);
    }
}

서블릿이 예외 처리를 위한 오류 페이지 정보를 확인할 수 있도록 한다.

 

ErrorPageController - 오류 처리 컨트롤러

package hello.exception.servlet;

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.RequestMapping;

import javax.servlet.RequestDispatcher;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

@Slf4j
@Controller
public class ErrorPageController {

    // RequestDispatcher 상수로 정의되어 있음
    public static final String ERROR_EXCEPTION = "javax.servlet.error.exception";
    public static final String ERROR_EXCEPTION_TYPE = "javax.servlet.error.exception_type";
    public static final String ERROR_MESSAGE = "javax.servlet.error.message";
    public static final String ERROR_REQUEST_URI = "javax.servlet.error.request_uri";
    public static final String ERROR_SERVLET_NAME = "javax.servlet.error.servlet_name";
    public static final String ERROR_STATUS_CODE = "javax.servlet.error.status_code";

    @RequestMapping("/error-page/404")
    public String errorPage404(HttpServletRequest request, HttpServletResponse response) {
        log.info("errorPage 404");
        printErrorInfo(request);
        return "error-page/404";
    }

    @RequestMapping("/error-page/500")
    public String errorPage500(HttpServletRequest request, HttpServletResponse response) {
        log.info("errorPage 500");
        printErrorInfo(request);
        return "error-page/500";
    }

    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)); // ex의 경우 NestedServletException 스프링이 한번 감싸서 반환
        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());
    }
}

오류가 발생했을 때 이를 처리하기 위한 컨트롤러이다.

예를 들어서 RuntimeException 예외가 발생하면 WebServerCustomizer의 errorPageEx에서 지정한 /error-page/500이 호출된다.

 

LogFilter

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");
    }
}

로그를 출력하는 부분에 request.getDispatcherType()을 추가한다.

 

WebConfig

@Configuration
public class WebConfig implements WebMvcConfigurer {

    @Bean
    public FilterRegistrationBean logFilter() {
        FilterRegistrationBean<Filter> filterRegistrationBean = new FilterRegistrationBean<>();
        filterRegistrationBean.setFilter(new LogFilter());
        filterRegistrationBean.setOrder(1);
        filterRegistrationBean.addUrlPatterns("/*");
        filterRegistrationBean.setDispatcherTypes(DispatcherType.REQUEST, DispatcherType.ERROR);

        return filterRegistrationBean;
    }
}

filter를 등록할 때 setDispatcherTypes()으로 원하는 Dispatcher 타입에만 해당 필터를 적용하도록 한다.

여기서는 REQUEST와 ERROR일 경우 logfilter를 거치도록 세팅했다.

 

로그 분석

2023-12-09 16:22:28.463  INFO 94242 --- [nio-8080-exec-1] hello.exception.filter.LogFilter         : REQUEST [e2042d33-bd7d-4bc0-b911-9bef878102b5][REQUEST][/error-ex] #1
2023-12-09 16:22:28.473  INFO 94242 --- [nio-8080-exec-1] hello.exception.filter.LogFilter         : EXCEPTION Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생! #2
2023-12-09 16:22:28.473  INFO 94242 --- [nio-8080-exec-1] hello.exception.filter.LogFilter         : RESPONSE [e2042d33-bd7d-4bc0-b911-9bef878102b5][REQUEST][/error-ex] #3
2023-12-09 16:22:28.475 ERROR 94242 --- [nio-8080-exec-1] 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: 예외 발생! #4
	at hello.exception.servlet.ServletExController.errorEx(ServletExController.java:16) ~[main/:na]

2023-12-09 16:22:28.477  INFO 94242 --- [nio-8080-exec-1] hello.exception.filter.LogFilter         : REQUEST [6fb09043-6bd4-4efe-b18c-c2e0626250cc][ERROR][/error-page/500] #5
2023-12-09 16:22:28.478  INFO 94242 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : errorPage 500 #6
2023-12-09 16:22:28.478  INFO 94242 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : ERROR_EXCEPTION: {}

java.lang.RuntimeException: 예외 발생!
	at hello.exception.servlet.ServletExController.errorEx(ServletExController.java:16) ~[main/:na]

2023-12-09 16:44:15.947  INFO 94668 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : ERROR_EXCEPTION_TYPE: class java.lang.RuntimeException
2023-12-09 16:44:15.947  INFO 94668 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : ERROR_MESSAGE: Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!
2023-12-09 16:44:15.947  INFO 94668 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : ERROR_REQUEST_URI: /error-ex
2023-12-09 16:44:15.947  INFO 94668 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : ERROR_SERVLET_NAME: dispatcherServlet
2023-12-09 16:44:15.947  INFO 94668 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : ERROR_STATUS_CODE: 500
2023-12-09 16:44:15.947  INFO 94668 --- [nio-8080-exec-1] h.exception.servlet.ErrorPageController  : dispatchType=ERROR 
2023-12-09 16:22:28.536  INFO 94242 --- [nio-8080-exec-1] hello.exception.filter.LogFilter         : RESPONSE [6fb09043-6bd4-4efe-b18c-c2e0626250cc][ERROR][/error-page/500] #7

 

1. REQUEST [e2042d33-bd7d-4bc0-b911-9bef878102b5][REQUEST][/error-ex]

• 클라이언트가 /error-ex로 HTTP 요청을 보내고 WAS → 필터 → 서블릿 → 인터셉터 → 컨트롤러 순으로 요청이 전파된다.
• 이때 필터에서 chain.doFilter()에 의해 필터가 연속적으로 호출되고, 더이상 호출될 필터가 없는 경우 서블릿을 호출한다. 서블릿에서 인터셉터를 거쳐 컨트롤러가 호출되고, 컨트롤러에서 예외가 발생한다.

 

2. EXCEPTION Request processing failed; nested exception is java.lang.RuntimeException: 예외 발생!

• 컨트롤러에서 예외가 발생했으므로 다시 컨트롤러에서 WAS로 역순으로 이동하며 예외가 전파된다.
• 이때 필터의 try/catch 문에 의해 위와 같은 로그가 출력된다.

 

3. RESPONSE [e2042d33-bd7d-4bc0-b911-9bef878102b5][REQUEST][/error-ex]

• try/catch 구문을 빠져나오면서 finally 구문이 실행된다.
• 이때까지는 예외가 컨트롤러에서 WAS까지 전파되는 도중이므로 DispatcherType이 REQUEST이다.

 

4. java.lang.RuntimeException: 예외 발생!

• WAS까지 예외가 성공적으로 전파되었다.

 

5. REQUEST [6fb09043-6bd4-4efe-b18c-c2e0626250cc][ERROR][/error-page/500]

• WAS에서 예외 정보를 확인한다.
• 예외가 WebServerCustomizer에 등록되어 있으므로(errorPageEx 객체) WAS는 내부적으로 error-page/500으로 요청을 보낸다.
• 이때 DisPatcherType은 ERROR이다.

 

6. errorPage 500

• WAS에서 error-page/500으로 요청 → 필터 → 서블릿 → 인터셉터 → 컨트롤러(/errorpage/500) 순으로 요청이 전파되면서 errorPage500 메서드 내부의 log.info()를 통해 로그가 출력된다.

 

7. RESPONSE [6fb09043-6bd4-4efe-b18c-c2e0626250cc][ERROR][/error-page/500]

• 컨트롤러에서 다시 WAS로 역순으로 이동한다. 이 과정에서 finally 구문이 호출된다.
• 이때는 서버에서 내부적으로 에러 페이지를 가져오기 위한 과정이었으므로 DispatcherType이 ERROR이다.