AOP/(Rest)ControllerAdvice Log를 꾸며보자(feat. NPE 관리)

클릭하면 큰 화면으로 볼 수 있습니다

version 1

version 2

맨 위 쿼리는 P6Spy를 이용해서 보여진 쿼리다. 저거 아니면 log4jdbc를 이용해서 볼 수도 있다.

저건 의존성 추가하고 Config 설정만 몇개 해주면 되서 패스하겠다.

밑에 보면 AOP(Aspect)에서 컨트롤러, 서비스단에서의 정보들을 로깅하고있는 것을 볼 수 있다.

애초에 내가 맥북을 쓰기때문에 다른 로그들도 [날짜] [LEVEL] [숫자] - 정보로 색이 입혀져서 뽑히는데

원래는 하얀색만 나온다는 것을 명심하자~~!^-^

저렇게 이뿌게 로그를 찍을라면 그냥 컬러를 주면서, 맞는 포인트컷, Around 설정과 jointPoint에서 정보를 가져오는정도만 코드를 작성해주면 된다.

추가로 커스텀예외에서 런타임으로 태워서 받는 Advice에서도 적용을 해 줄 수 있다.

Aspect들은 파란색, 예외는 빨간색으로 뜨도록 만들어놨다.

이뿌지않은가~~하핫

구글링 + 예전에 내가 만든 프로젝트 aop를 참고해서 만들었다.

아예 스트링으로 때려 박는 방법과 맵에 넣는 방법이 있는데, 그냥 HashMap은 순서를 보장하지 않기때문에 포맷이 이쁘게 안나온다. 그래서 LinkedHashMap을 사용했다.

혹시라도 이런 별거없는 블로그에서 내용을 인용해가거나 써갈 분이 계실수있는데 출처만 남겨주시면 감사하겠습니다~

log는 롬복에 붙어있는 구현체를 이용했다. logback을 쓰든, log4j를 쓰든 자기 마음이다

 

1. AOP부분

import java.text.SimpleDateFormat;
import java.util.Arrays;
import java.util.Calendar;
import java.util.Enumeration;
import java.util.LinkedHashMap;
import java.util.Map;
import java.util.Objects;
import javax.servlet.http.HttpServletRequest;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.json.JSONObject;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

@Slf4j
@Component
@Aspect
public class ExecutionLogAspect {

    public static final String ANSI_RESET = "\u001B[0m";
    public static final String ANSI_BLACK = "\u001B[30m";
    public static final String ANSI_RED = "\u001B[31m";
    public static final String ANSI_GREEN = "\u001B[32m";
    public static final String ANSI_YELLOW = "\u001B[33m";
    public static final String ANSI_BLUE = "\u001B[34m";
    public static final String ANSI_PURPLE = "\u001B[35m";
    public static final String ANSI_CYAN = "\u001B[36m";
    public static final String ANSI_WHITE = "\u001B[37m";

    @Pointcut("execution(* com.boki.realworld.api..*Controller.*(..))")
    public void ControllerLog() {
    }

    @Around("ControllerLog()")
    public Object ExecutionLog(ProceedingJoinPoint joinPoint) throws Throwable {
        Object result = joinPoint.proceed();
        HttpServletRequest request = ((ServletRequestAttributes) Objects.requireNonNull(
            RequestContextHolder.getRequestAttributes())).getRequest();

        String controllerName = joinPoint.getSignature().getDeclaringType().getSimpleName();
        String methodName = joinPoint.getSignature().getName();

        Map<String, Object> params = new LinkedHashMap<>();
        try {
            params.put("controller", ANSI_GREEN + controllerName + ANSI_RESET);
            params.put("method", ANSI_BLUE + methodName + ANSI_RESET);
            params.put("params", ANSI_PURPLE + getParams(request) + ANSI_RESET);
            params.put("log_time", ANSI_YELLOW + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(
                Calendar.getInstance().getTime()) + ANSI_RESET);
            params.put("request_uri", ANSI_CYAN + request.getRequestURI() + ANSI_RESET);
            params.put("http_method", ANSI_RED + request.getMethod() + ANSI_RESET);
        } catch (Exception e) {
            log.error("LoggerAspect - Controller error", e);
        }
        log.info(ANSI_CYAN + "\nControllerLogAspect" + ANSI_RESET + " : {}\n", params);
        return result;
    }

    private static JSONObject getParams(HttpServletRequest request) {
        JSONObject jsonObject = new JSONObject();
        Enumeration<String> params = request.getParameterNames();
        while (params.hasMoreElements()) {
            String param = params.nextElement();
            String replaceParam = param.replaceAll("\\.", "-");
            jsonObject.put(replaceParam, request.getParameter(param));
        }
        return jsonObject;
    }

    @Pointcut("execution(* com.boki.realworld.api..*Service.*(..))")
    public void ServiceLog() {
    }

    @Around("ServiceLog()")
    public Object methodLogger(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        Object result = proceedingJoinPoint.proceed();

        String serviceName = proceedingJoinPoint.getSignature().getDeclaringType().getSimpleName();
        String methodName = proceedingJoinPoint.getSignature().getName();

        Map<String, Object> params = new LinkedHashMap<>();

        try {
            params.put("service", ANSI_GREEN + serviceName + ANSI_RESET);
            params.put("method", ANSI_BLUE + methodName + ANSI_RESET);
            params.put("params", ANSI_PURPLE + Arrays.toString(proceedingJoinPoint.getArgs()) + ANSI_RESET);
            params.put("log_time", ANSI_YELLOW + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(Calendar.getInstance().getTime()) + ANSI_RESET);
        } catch (Exception e) {
            log.error("LoggingAspect - Service error", e);
        }
        log.info(ANSI_CYAN + "\nServiceLogAspect" + ANSI_RESET + " : {}\n", params);
        return result;
    }
}

2. RestControllerAdvice

package com.boki.realworld.common.advice;

import static org.springframework.http.HttpStatus.BAD_REQUEST;
import static org.springframework.http.HttpStatus.INTERNAL_SERVER_ERROR;
import static org.springframework.http.HttpStatus.NOT_FOUND;
import static org.springframework.http.HttpStatus.UNPROCESSABLE_ENTITY;

import com.boki.realworld.common.exception.BadRequestException;
import com.boki.realworld.common.exception.DuplicatedException;
import com.boki.realworld.common.exception.NotFoundException;
import java.text.SimpleDateFormat;
import java.util.Calendar;
import java.util.Set;
import javax.servlet.http.HttpServletRequest;
import javax.validation.ConstraintViolation;
import javax.validation.ConstraintViolationException;
import lombok.extern.slf4j.Slf4j;
import org.springframework.http.HttpStatus;
import org.springframework.http.ResponseEntity;
import org.springframework.validation.BindException;
import org.springframework.web.bind.annotation.ExceptionHandler;
import org.springframework.web.bind.annotation.RestControllerAdvice;
import org.springframework.web.method.HandlerMethod;

@Slf4j
@RestControllerAdvice
public class ControllerAdvice {

    public static final String ANSI_RESET = "\u001B[0m";
    public static final String ANSI_BLACK = "\u001B[30m";
    public static final String ANSI_RED = "\u001B[31m";
    public static final String ANSI_GREEN = "\u001B[32m";
    public static final String ANSI_YELLOW = "\u001B[33m";
    public static final String ANSI_BLUE = "\u001B[34m";
    public static final String ANSI_PURPLE = "\u001B[35m";
    public static final String ANSI_CYAN = "\u001B[36m";
    public static final String ANSI_WHITE = "\u001B[37m";
    public static final String RED_UNDERLINED = "\033[4;31m";

    @ExceptionHandler(BadRequestException.class)
    public ResponseEntity<ErrorResponse> badRequestException(BadRequestException e,
        HandlerMethod method, HttpServletRequest request) {
        exactErrorLog(e, method, BAD_REQUEST, request);
        return ResponseEntity.badRequest().body(ErrorResponse.from(e.getMessage()));
    }

    @ExceptionHandler(DuplicatedException.class)
    public ResponseEntity<ErrorResponse> badRequestException(DuplicatedException e,
        HandlerMethod method, HttpServletRequest request) {
        exactErrorLog(e, method, BAD_REQUEST, request);
        return ResponseEntity.badRequest().body(ErrorResponse.from(e.getMessage()));
    }

    @ExceptionHandler(NotFoundException.class)
    public ResponseEntity<ErrorResponse> notFoundException(NotFoundException e,
        HandlerMethod method, HttpServletRequest request) {
        exactErrorLog(e, method, NOT_FOUND, request);
        return ResponseEntity.status(HttpStatus.NOT_FOUND).body(ErrorResponse.from(e.getMessage()));
    }

    @ExceptionHandler(BindException.class)
    public ResponseEntity<ErrorResponse> bindException(BindException e, HandlerMethod method,
        HttpServletRequest request) {
        exactErrorLog(e, method, UNPROCESSABLE_ENTITY, request);
        return ResponseEntity.unprocessableEntity().body(ErrorResponse.from(e.getBindingResult()));
    }

    @ExceptionHandler(ConstraintViolationException.class)
    public ResponseEntity<ErrorResponse> constraintException(ConstraintViolationException e,
        HandlerMethod method, HttpServletRequest request) {
        exactErrorLog(e, method, BAD_REQUEST, request);
        Set<ConstraintViolation<?>> violations = e.getConstraintViolations();
        String errorMessage;
        if (!violations.isEmpty()) {
            StringBuilder builder = new StringBuilder();
            violations.forEach(violation -> builder.append(violation.getMessage()).append(" "));
            errorMessage = builder.toString();
        } else {
            errorMessage = "ConstraintViolationException occurred.";
        }
        return ResponseEntity.badRequest().body(ErrorResponse.from(errorMessage));
    }

    @ExceptionHandler(Exception.class)
    public ResponseEntity<ErrorResponse> exception(Exception e, HandlerMethod method,
        HttpServletRequest request) {
        exactErrorLog(e, method, INTERNAL_SERVER_ERROR, request);
        return ResponseEntity.internalServerError().body(ErrorResponse.from(e.getMessage()));
    }

    private void exactErrorLog(Exception e, HandlerMethod handlerMethod, HttpStatus httpStatus, HttpServletRequest request) {
        String errorDate = ANSI_YELLOW + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(Calendar.getInstance().getTime()) + ANSI_RESET;
        String requestURI = ANSI_CYAN + request.getRequestURI() + ANSI_RESET;
        String exceptionName = ANSI_PURPLE + e.getClass().getSimpleName() + ANSI_RESET;
        String status = ANSI_RED + httpStatus.toString() + ANSI_RESET;
        String controllerName = ANSI_GREEN + handlerMethod.getMethod().getDeclaringClass().getSimpleName() + ANSI_RESET;
        String methodName = ANSI_BLUE + handlerMethod.getMethod().getName() + ANSI_RESET;
        String message = ANSI_RED + e.getMessage() + ANSI_RESET;
        String lineNumber = RED_UNDERLINED + e.getStackTrace()[0].getLineNumber() + ANSI_RESET;
        logger.error("\n[Time: {} | Class: {} | Method: {} | LineNumber: {} | Path: {} | Exception: {} | Status: {} | Message: {}]\n", errorDate, controllerName, methodName, lineNumber, requestURI, exceptionName, status, message);
    }
}

너무너무 이쁘게 만든거같아서 뿌듯하다. (나는 누군가의 글을 베끼지않는다. 검색하고 조합으로 나온 이쁜 코드를 적는 것 뿐)

 

3. 컨트롤러

에 직접 예외를 날려서 잘 되는지 테스트를 해보았다

    @GetMapping("/test1")
    public String test1(Authentication auth) {
        log.info("auth - {}", auth);
        if(auth == null) throw new NotFoundException("유저가 없습니다");
        return "test1";
    }

+

 

추가로 NPE(Null Pointer Exception)일때 전역적으로 특정한 객체의 예외일때만 메세지를 다르게 줄 수 있다

(어차피 stacktrace나 로그 따라 올리고 소스코드를 보면 알 수 있지만, 신입인 경우 혹은 소스코드가 복잡한 경우 찾기 어려울 수가 있다)

이번에는 Authentication을 들어볼 것이다.

사실 Spring Cloud Gateway를 사용하거나 SecurityConfig에서 path마다 authenticate 여부를 지정해주거나 @PreAuthorize("#... or hasAnyRole(...), isAnonymous(...)) 등을 사용하거나 컨트롤러에서 auth==null이면 RuntimeException을 throw해주거나 한다면 Authentication의 존재여부에 따라 핸들링을 할 수 있겠지만, 그런 로직 없이 Authentication을 쓰면서 참조를 하게되면 NPE를 만나게 될 것이다.

그럴때는 이렇게 해줄 수 있다. [ 개발자를 위해서 ]

# 컨트롤러

원래는 //memo 부분처럼 Authentication의 principal이나 credential, authorities가 필요하면 앞에 객체가 메모리에 올라와있는지부터 체크를 하는게 맞긴하다. 하지만 사람은, 개발자라면 실수할 수 있는법.

또한 내가 아닌 다른 사람은 다른 스타일로 코딩할 수도 있는거다. 혹은 API 명세만 보고 작업하는 프론트엔드 사람이라던지 등등

특히나 자주 사용되는 참조메서드의 객체라면 NPE에서 따로 잡아줘도 될거같다

 

# 어드바이스

# 포스트맨 결과

아니면 파라미터에 @NonNull을 붙이거나 @Nullable을 붙여서 로직을 처리할수도 있다

public String test1(@NonNull Authentication auth) {
	...
}

public String test1(@Nullable Authentication auth) {
	...
}

이 포스팅을 작성하다가 신기한 사실을 알아냈다

# 1.
public String test1(Authentication authentication) {
	...
}

# 2.
public String test2() {
    Authentication authentication = SecurityContextHolder.getContext().getAuthentication();

}

1번 코드와 2번 코드는 과연 같은 Authentication을 가지고 올까요?

답은 Yes And No이다. 스프링 시큐리티에서 전략을 좀 다르게 갖고있는 것 같다..(댓글로 설명좀..ㅎㅎ..)

같은 토큰으로 로그인을 했을 때의 해시코드가 같다

이번에는 No Auth로 api를 호출해보겠다

test1의 경우에는 NPE, 즉 널포인터 익셉션이 발생한 대신에

test2의 경우에는 NPE가 뜨지 않으며, 익명 유저를 갖고 온다

그럼 마지막으로, 토큰과 함께 api test1과 미인증 상태로 api test2의 해시코드는 같을까? 아마 당연히 다를 것 같다

다르더라~

결국 내가 깔쌈하게 Java8버전의 Optional을 이용해서 NPE를 피하려고 했던 이 코드는 

public static Authentication getAuthentication() {
    Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
    return Optional.ofNullable(authentication)
        .orElseThrow(() -> new RuntimeException("로그인을 하지 않았을껄?"));
}

NULL이 들어오지 않기때문에 예외가 날라가지 않았다

결국 if나 ObjectUtils 등으로 체크해주거나 entryPoint마다 auth를 다르게 주는방법들이 필요한것 같다.

추가로 auth가 없을때도 성공하는 로직이 필요하다면 이런 3항연산자를 고려해볼 수 있다.

String userEmail = "test1234@test.com";
userEmail = authentication == null ? userEmail : String.valueOf(authentication.getPrincipal());

음 다음편으로는 SpringSecurity를 다뤄볼까한닷

 

+

 

추가로 버전 2를 업데이트했다

오류가 났을 때 에러 줄 수까지 출력해주면 좋겠다 싶어서 포맷을 바꿨다

private void exactErrorLog(Exception e, HandlerMethod handlerMethod, HttpStatus httpStatus, HttpServletRequest request) {
    if(activeProfile.equals(Env.local.name())) {
        e.printStackTrace();
    }
    String errorDate = ANSI_YELLOW + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(Calendar.getInstance().getTime()) + ANSI_RESET;
    String requestURI = ANSI_CYAN + request.getRequestURI() + ANSI_RESET;
    String exceptionName = ANSI_PURPLE + e.getClass().getSimpleName() + ANSI_RESET;
    String status = ANSI_RED + httpStatus.toString() + ANSI_RESET;
    String controllerName = ANSI_GREEN + handlerMethod.getMethod().getDeclaringClass().getSimpleName() + ANSI_RESET;
    String methodName = ANSI_BLUE + handlerMethod.getMethod().getName() + ANSI_RESET;
    String message = ANSI_RED + e.getMessage() + ANSI_RESET;
    String lineNumber = RED_UNDERLINED + e.getStackTrace()[0].getLineNumber() + ANSI_RESET;
    log.error("\n[Time: {} | Class: {} | Method: {} | LineNumber: {} | Path: {} | Exception: {} | Status: {} | Message: {}]\n", errorDate, controllerName, methodName, lineNumber, requestURI, exceptionName, status, message);
}

에러가 난 라인 넘버는 이 의미다

73 번째 줄. 즉 72번째 메서드 내부

여기서 의문이 들 수 있다

아니, 그냥 e.printStackTrace();하면 되는거아녀?

이렇게말이다. 회색이 아닌 컬러로 칠해진 곳을 a태그처럼 누르면 어디에서 에러가 났는지 따라 들어갈 수도있다.

하지만 e.printStackTrace(); 개발단계에서만, 혹은 개발 단계에서도 최대한 주의해서 써야한다.

 

장점

• 예외 발생 당시의 호출 스택(Call Stack)에 있던 메소드의 정보와 예외 결과를 화면에 출력함
• 예외 상황을 분석하기 위한 용도로 사용(개발자에게 디버깅할 수 있는 힌트를 제공)

단점

• printStackTrace()를 call할 경우 System.err로 쓰여져서 제어하기가 힘듦
• printStackTrace()는 java 리플렉션을 사용하여 추적하는 것이라서 많은 오버헤드가 발생할 수 있음
• printStackTrace()는 서버에서 스택정보를 취합하기 때문에 서버에 부하가 발생할 수 있음
• printStackTrace()는 출력이 어디로 가는지 파악하기가 어려움(톰캣같은경우는 catalina.out에 남음)
• printstackTrace()는 관리가 힘듬(보통 log4j, logback과 같은 로깅 라이브러리를 사용하여, 로그 패턴 및 로그 메시지를 지정 및 콘솔로그 / 파일로그 형태로 관리할 수 있음)

참조

https://tgyun615.com/59 

[JAVA] e.printStackTrace() 사용하지 말아야하는 이유

결론적으로 장점보다 단점이 많은 것이라 할 수 있다.

그럼 쓰지 말아야할까? 기본적으로 안전하게 코딩을 하려면 맞다. 하지만 꼭 그렇지는 않다. local이나 dev profile정도에서만 활성화시키고, 다른 환경에서는 출력되지 않게 하는 방법도 있다.

혹시라도 여러 profiles로 실행을 하면서

Unable to start embedded Tomcat 에러를 마주쳤다면

dependencies 안에 야무지게 넣어주자!!

maven: 

<dependency> 
    <groupId>org.springframework.boot</groupId> 
    <artifactId>spring-boot-starter-tomcat</artifactId> 
</dependency>

gradle:

implementation 'org.springframework.boot:spring-boot-starter-tomcat:2.6.4'

이제 작업..

public enum Env {
    local, dev, prod, test
}

이렇게 common 패키지에 추가해준다.(스트링으로만 해줘도 상관없음)

그리고 application.yaml, application-local.yaml, application-prod.yaml 3개를 만든다

# applcation.yaml
spring:
  profiles:
    active: local
    
# application-local.yaml
server:
....

# application-prod.yaml
server:
.....

@Slf4j
@RestControllerAdvice
public class ControllerAdvice {

    @Value("${spring.profiles.active}")
    private String activeProfile;

	......
}

if(activeProfile.equals(Env.local.name())) {
    e.printStackTrace();
}

로컬 개발 환경일때만 에러 로그를 출력하겠다 이 말이다.

참고로 profiles 설정은 하나의 yaml에 --- 구분자로 여러 profiles들을 입력하는 방법과, 저렇게 여러 파일을 나누는 방법, 그리고 @Profile("dev") 어노테이션 방식, 인텔리제이 Run/Debug Configurations Tab의 속성에서 넣어주는 방법이 있다

추가로 그룹으로 주는 방법도 있다는데 밑의 밸덩님의 사이트에서 볼 수 있다

https://www.baeldung.com/spring-profiles

이제 로컬에서 에러 로깅을 해보면

local 환경으로 실행했다

테스트

e.printStackTrace();

아주 잘찍힌다 이제는 prod환경으로 해보자

막간으로 개발 환경에 대한 네이밍은 여기를 참고하자

https://bcho.tistory.com/759

개발 환경(dev,stage,qa,production)

prod 환경

순수한 에러 로그만 출력된다

라인 번호도 나와있으니 컨트롤러와 메서드를 잘 찾아가면 문제를 해결할수있을것이다. 이정도면 많이 친절한듯 ㅎㅎ

그럼 추가 포스팅 끝!!