Runtime Error log 관련 질문

Question

log를 보면 Runtime error log가 2번 찍히는데, -> 첫번째 요청에서, errorEx() 컨트롤러에 의해 throw new RuntimeException("예외 발생!"); -> 첫번째 요청에서, error 발생 이후 WAS로 역전파 되는 과정에서 filter에 의해 } catch (Exception e) { log.info("EXCEPTION!!"); throw e; 총 2번 찍힌다고 생각했습니다. 그런데 Log의 순서를 보면 컨트롤러 내부의 printErrorInfo가 호출되는 과정에서 runtime error Log가 찍힙니다. 이것이 단순히 log가 찍히는 속도의 차이에 의한 것인지, 아니면 실제로 다른 곳에서 error가 발생해서 log가 찍힌것인지 궁금합니다.

y2gcoder · Answer

안녕하세요. 홍산해님, 공식 서포터즈 y2gcoder입니다. 먼저 에러 로그가 발생하는 위치에 대해 질문을 해주셨습니다. 먼저 이해를 돕기 위해 예외 발생과 오류 페이지 흐름과 보내주신 에러 로그 사진을 보여드리면서 시작하겠습니다. 1. WAS(여기까지 전파) <- 필터 <- 서블릿 <- 인터셉터 <- 컨트롤러(예외발생) 2. WAS /error-page/500 다시 요청 -> 필터 -> 서블릿 -> 인터셉터 -> 컨트롤러(/error- page/500) -> View 첫번째 로그는 컨트롤러에서 기록하는 것이 아니라 보시면 DispatcherServlet 이라는 곳에서 로깅해주고 있는 것을 아실 수 있습니다. 그래서 오류 흐름으로 보면 필터를 지나쳐 WAS로 가는 것을 보실 수 있습니다. 그리고 영한님께서도 해당 강의 9분 30초부터 WAS에서 첫번째 로깅을 해주고 있다고 말씀해주고 계십니다. 두번째 로그는 ErrorPageController의 printErrorInfo 중 log.info ("ERROR_EXCEPTION: {}", request.getAttribute(ERROR_EXCEPTION)): 에서 로깅해주고 있습니다. 문서에서는 원래 log.info ("ERROR_EXCEPTION: ex=", request.getAttribute(ERROR_EXCEPTION)): 로 되어있는데 전 강의인 서블릿 예외 처리 - 오류 페이지 작동 원리 의 7분 25초 대부터 보시면 위의 부분처럼 로깅을 해주고 계시고, log.info의 두번째 자리에 exception을 넣었기 때문에, ERROR_EXCEPTION: {} 의 {}에 해당 내용이 들어가지 않고, 그 밑의 줄에 Exception의 stacktrace 내용이 호출된 것 같습니다. 감사합니다.