Album 프로젝트는 초기에 로그 기능의 필요성을 고려하지 못하여 로그 기능 없이 배포되었다.
이후 어플리케이션의 동작 과정, 에러 발생 지점 파악, 성능 분석 등을 위해 로그 기능은 거의 필수적이라는 것을 알게 되었다.
그래서 스프링 AOP를 통해 아래의 요구사항을 충족하는 로그 기능을 Album 프로젝트에 추가해보고자 한다.
- Persistence, Business, Presentation 계층의 public 메소드 호출 및 종료에 대한 로그를 남긴다.
- 클라이언트 요청 별로 로그를 구별할 수 있다.
- 로그에는 메소드 정보, 메소드 호출 깊이, 수행 시간이 표현된다.
- 메소드 정상 종료와 예외 종료를 구별할 수 있다.
로그 클래스
LogId
LogId는 이번 로그 기능의 가장 기본이 되는 클래스이다.
LogId는 특정 메소드 호출 전, 종료 후에 생성된다.
필드로 String id, int depth를 갖고 있다.
- id는 로그 아이디를 의미한다. 클라이언트 요청 별로 동일한 값을 유지하게 된다.
- depth는 메소드 호출 깊이를 의미한다. 예를 들어 MemberController.method() -> MemberService.method() -> MemberRepository.method()로 메소드 호출이 발생한다고 가정하자. MemberController.method()의 깊이는 0, MemberService.method()의 깊이는 1, MemberRepository.method()의 깊이는 2가 된다.
기본 생성자로 LogId 객체를 생성하면, 해당 객체는 무작위한 8자리의 id, 0의 depth를 갖는다.
그리고 createNext(), createPrev(), isZeroDepth()가 정의되어있다.
- createNext()는 다음 깊이의 메소드에 대한 LogId 객체를 생성하기 위해 사용된다.
- createPrev()는 이전 깊이의 메소드에 대한 LogId 객체를 생성할 때 사용된다.
- isZeroDepth()는 LogId의 depth가 0인지를 판별할 때 사용된다.
@Getter
public class LogId {
// 로그 아이디. http 클라이언트 요청 별로 동일한 값 유지
private final String id;
// 메소드 호출 깊이. ex) memberController.method() -> memberService.method() -> MemberRepository.method()
private final int depth;
public LogId() {
this.depth = 0;
this.id = createId();
}
// createNext(), createPrev()를 위한 생성자
private LogId(String id, int depth) {
this.id = id;
this.depth = depth;
}
// 로그 아이디 생성
private String createId() {
return UUID.randomUUID().toString().substring(0, 8);
}
public LogId createNext() {
return new LogId(id, depth + 1);
}
public LogId createPrev() {
return new LogId(id, depth - 1);
}
public boolean isZeroDepth() {
return depth == 0;
}
}
LogStatus
LogStatus는 특정 메소드에 대한 로그를 남기기 위한 정보를 갖고 있는 클래스이다.
LogId logId, Long startTime, String message 필드를 갖고 있다.
- logId는 로그 아이디, 메소드 호출 깊이의 정보를 갖는다.
- startTime은 메소드 호출 시간을 의미한다. 이후 메소드의 수행 시간을 측정하기 위해 사용된다.
- message는 메소드의 정보를 갖는다.
@Getter
public class LogStatus {
private final LogId logId;
private final Long startTime;
private final String message;
public LogStatus(LogId logId, Long startTime, String message) {
this.logId = logId;
this.startTime = startTime;
this.message = message;
}
}
LogTrace
LogTrace는 LogId, LogStatus를 통해 실질적으로 로그 기능을 수행하는 클래스이다.
String START_PREFIX, String COMPLETE_PREFIX, String EX_PREFIX라는 클래스 필드를 갖고 있다.
- START_PREFIX는 메소드 호출 전 로그를 위해 사용되는 꾸밈 문자열이다.
- COMPLETE_PREFIX는 메소드가 정상 종료된 후의 로그를 위해 사용되는 꾸밈 문자열이다.
- EX_PREFIX는 메소드가 예외 종료된 후의 로그를 위해 사용되는 꾸밈 문자열이다.
그리고 ThreadLocal<LogId> curLogId 필드를 갖고 있다.
curLogId는 현재 메소드에 대한 LogId를 담기 위한 필드이다.
클라이언트 요청 별로 동일한 LogId.id를 유지하기 위해 ThreadLocal을 사용하였다.
많은 메소드가 정의되어 있는데, 우선 메소드 호출 전 로그를 찍기 위한 syncLogId(), begin()을 살펴보자.
- syncLogId()는 메소드 호출 전 로그를 찍기 전에 LogId를 동기화 하기 위한 메소드이다.
- curLogId가 null인 경우, 즉 호출할 메소드의 깊이가 0이라면 새로운 id와 0의 depth를 가진 LogId를 생성하고 curLogId에 담는다.
- 만약 curLogId가 null이 아닌 경우, 즉 호출할 메소드의 깊이가 1 이상이라면 id는 유지하면서 +1된 depth를 가진 LogId를 생성하고 curLogId에 담는다.
- begin()은 메소드 호출 로그를 찍기 위한 메소드이다. 호출할 메소드 정보를 의미하는 String message를 파라미터로 가진다.
- 우선 syncLogId()를 호출해서 LogId를 동기화 한다.
- 로그 아이디, 메소드 정보를 포함하는 메소드 호출 로그를 찍는다.
- 호출할 메소드의 LogId, startTime, message를 가진 LogStatus를 반환한다.
이제 메소드 종료 후 로그를 찍기 위한 releaseLogId(), complete(), end(), exception()을 살펴보자.
- releaseLogId()는 메소드 종료 후 로그를 찍은 후 LogId를 이전 깊이의 메소드로 동기화하기 위한 메소드이다.
- 만약 curLogId에 저장된 LogId의 깊이가 0이라면, 현재 메소드의 깊이가 0이며 이전 메소드는 존재하지 않는 다는 것을 의미한다. curLogId에 저장된 LogId를 삭제해준다.
- 만약 curLogId에 저장된 LogId의 깊이가 0이 아니라면, 현재 메소드의 깊이가 1 이상이며 이전 메소드가 존재한다는 의미이다. id는 유지하면서 -1된 depth를 가진 LogId를 생성하고 curLogId에 담는다.
- complete()는 메소드 종료 후 로그를 찍기 위한 메소드이다. 파라미터로 LogStatus status, Exception e를 가진다.
- 우선 현재 시간 - status.startTime을 통해 메소드 수행 시간을 산출한다.
- 만약 e가 null이라면 메소드가 정상 종료된 것이다. 그에 맞는 로그를 출력한다.
- 만약 e가 null이 아니라면 메소드가 예외 종료된 것이다. 그에 맞는 로그를 출력한다.
- 마지막으로 releaseLogId()를 호출한다.
- end()는 메소드 정상 종료 로그를 찍기 위한 메소드이다. 종료된 현재 메소드에 대한 LogStatus status를 파라미터로 가진다.
- complete(status, null)을 호출하여 메소드 정상 종료 로그를 찍는다.
- complete(status, null) 내부에서 releaseLogId()를 호출하여 LogId를 이전 깊이의 메소드로 동기화 한다.
- exception()은 메소드 예외 종료 로그를 찍기 위한 메소드이다. 종료된 현재 메소드에 대한 LogStatus status, 발생환 예외에 대한 Exception e를 파라미터로 가진다.
- complete(status, e)를 호출하여 메소드 예외 종료 로그를 찍는다.
- complete(status, e) 내부에서 releaseLogId()를 호출하여 LogId를 이전 깊이의 메소드로 동기화 한다.
@Slf4j
public class LogTrace {
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
private ThreadLocal<LogId> curLogId = new ThreadLocal<>();
public LogStatus begin(String message) {
syncLogId();
LogId logId = curLogId.get();
Long startTime = System.currentTimeMillis();
log.info("[{}] {}{}", logId.getId(), decorateLog(START_PREFIX, logId.getDepth()), message);
return new LogStatus(logId, startTime, message);
}
public void end(LogStatus status) {
complete(status, null);
}
public void exception(LogStatus status, Exception e) {
complete(status, e);
}
private void syncLogId() {
LogId logId = curLogId.get();
if (logId == null) {
curLogId.set(new LogId());
} else {
curLogId.set(logId.createNext());
}
}
private void complete(LogStatus status, Exception e) {
Long stopTimeMs = System.currentTimeMillis();
long resultTimeMs = stopTimeMs - status.getStartTime();
LogId logId = status.getLogId();
if (e == null) {
log.info("[{}] {}{} time={}ms", logId.getId(), decorateLog(COMPLETE_PREFIX, logId.getDepth()), status.getMessage(), resultTimeMs);
} else {
log.info("[{}] {}{} time={}ms ex={}", logId.getId(), decorateLog(EX_PREFIX, logId.getDepth()), status.getMessage(), resultTimeMs, e.toString());
}
releaseLogId();
}
private void releaseLogId() {
LogId logId = curLogId.get();
if (logId.isZeroDepth()) {
curLogId.remove();
} else {
curLogId.set(logId.createPrev());
}
}
private static String decorateLog(String prefix, int depth) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < depth; i++) {
sb.append( (i == depth - 1) ? "|" + prefix : "| ");
}
return sb.toString();
}
}
스프링 AOP 클래스
Pointcuts
Pointcuts에는 어드바이스에 적용할 포인트컷들을 정의해두었다.
- allRepository()는 public 접근 제한자를 가진 *Repository* 클래스의 조인포인트에 어드바이스를 적용한다.
- allService()는 public 접근 제한자를 가진 *Service* 클래스의 조인포인트에 어드바이스를 적용한다.
- allController()는 public 접근 제한자를 가진 *allController* 클래스의 조인포인트에 어드바이스를 적용한다.
- allMatch()는 allRepository(), allService(), allController()를 ||로 조합한 포인트컷을 제공한다. 따라서 allMatch()를 포인트컷으로 사용하면, public 접근 제한자를 가진 *Repository*, *Service*, *Controller* 클래스의 조인포인트에 어드바이스가 적용된다.
public class Pointcuts {
@Pointcut("execution(public * com.maeng0830.album..*Repository*.*(..))")
public void allRepository() {}
@Pointcut("execution(public * com.maeng0830.album..*Service*.*(..))")
public void allService() {}
@Pointcut("execution(public * com.maeng0830.album..*Controller*.*(..))")
public void allController() {}
@Pointcut("allRepository() || allService() || allController()")
public void allMatch() {}
}
LoggingAspect
LoggingAspect는 @Asepct 클래스이다.
String POINTCUT_PACKAGE, LogTrace logTrace를 필드로 가진다.
- POINTCUT_PACKAGE는 외부 포인트컷이 위치한 패키지 정보를 값으로 가진다.
- logTrace는 로그 기능을 위한 필드이다.
doLog()는 로그 기능을 제공하는 어드바이스이다.
@Around(POINTCUT_PACKAGE + "allMathc()")가 적용되어있기 때문에 public 접근 제한자를 가진 *Repository*, *Service*, *Controller* 클래스의 조인포인트에 해당 어드바이스가 적용될 것이다.
- 어드바이스가 적용되는 클래스의 메소드 호출이 발생하면, 프록시 객체의 doLog()가 실행된다.
- joinPoint.getSignature().toShortString()을 통해 어드바이스가 적용되는 메서드에 대한 정보를 가져온다.
- logTrace.begin(messags)을 통해 메서드에 대한 정보를 넘겨주면서 메서드 호출 전 로그를 찍는다.
- joinPoint.proceed()를 통해 메서드를 호출한다.
- 만약 메서드가 정상 종료되었으면 logTrace.end(logStatus)를 통해 메서드 정상 종료 로그를 찍는다. 그리고 메서드 반환 값을 반환한다.
- 만약 메서드가 예외 종료되었으면 logTrace.exception(logStatus, e)를 통해 메서드 예외 종료 로그를 찍는다. 예외를 그대로 던져준다.
@Aspect
public class LoggingAspect {
private static final String POINTCUT_PACKAGE = "com.maeng0830.album.common.aop.Pointcuts.";
private final LogTrace logTrace;
public LoggingAspect(LogTrace logTrace) {
this.logTrace = logTrace;
}
@Around(POINTCUT_PACKAGE + "allMatch()")
public Object doLog(ProceedingJoinPoint joinPoint) throws Throwable {
LogStatus logStatus = null;
try {
String message = joinPoint.getSignature().toShortString();
logStatus = logTrace.begin(message); // 현재 메소드 호출 로깅
Object result = joinPoint.proceed();// 현재 메소드 호출
logTrace.end(logStatus); // 현재 메소드 정상 종료 로깅
return result;
} catch (Exception e) {
logTrace.exception(logStatus, e); // 현재 메소드 예외 종료 로깅
throw e;
}
}
}
AopConfig
AopConfig는 위의 로그 기능을 사용하기 위한 설정 클래스이다.
LoggingAspect.doLog()가 적용될 타입의 프록시 객체를 AutoProxyCreator를 통해 자동으로 생성하기 위해 LoggingAspect를 스프링 빈으로 등록한다.
@Configuration
public class AopConfig {
@Bean
public LogTrace logTrace() {
return new LogTrace();
}
@Bean
public LoggingAspect loggingAspect() {
return new LoggingAspect(logTrace());
}
}
적용 결과
Album 프로젝트의 댓글 등록 기능을 정상 수행 2번, 예외 수행 1번 실시했다.
아래는 로그 결과는 다음과 같다.
- 클라이언트 요청 별로 로그 아이디가 동일하게 유지되었다.
- 메소드 호출 및 종료에 대한 로그가 남겨졌다.
- 로그에는 메소드 정보, 메소드 호출 깊이, 메소드 수행 시간(종료 로그)가 포함되어있다.
- 메소드 정상 종료와 예외 종료를 구별할 수 있다.
## 정상 수행 1번
[2a99152f] CommentController.comment(..)
[2a99152f] |-->CommentService.comment(..)
[2a99152f] | |-->CrudRepository.findById(..)
[2a99152f] | |<--CrudRepository.findById(..) time=1ms
[2a99152f] | |-->CrudRepository.findById(..)
[2a99152f] | |<--CrudRepository.findById(..) time=1ms
[2a99152f] | |-->CrudRepository.save(..)
[2a99152f] | |<--CrudRepository.save(..) time=1ms
[2a99152f] |<--CommentService.comment(..) time=3ms
[2a99152f] CommentController.comment(..) time=4ms
## 정상 수행 2번
[c49b2d49] CommentController.comment(..)
[c49b2d49] |-->CommentService.comment(..)
[c49b2d49] | |-->CrudRepository.findById(..)
[c49b2d49] | |<--CrudRepository.findById(..) time=1ms
[c49b2d49] | |-->CrudRepository.findById(..)
[c49b2d49] | |<--CrudRepository.findById(..) time=0ms
[c49b2d49] | |-->CrudRepository.save(..)
[c49b2d49] | |<--CrudRepository.save(..) time=1ms
[c49b2d49] |<--CommentService.comment(..) time=2ms
[c49b2d49] CommentController.comment(..) time=4ms
## 예외 수행
[0adb2269] CommentController.comment(..)
[0adb2269] |-->CommentService.comment(..)
[0adb2269] |<X-CommentService.comment(..) time=1ms ex=com.maeng0830.album.common.exception.AlbumException: 로그인이 필요합니다.
[0adb2269] CommentController.comment(..) time=3ms ex=com.maeng0830.album.common.exception.AlbumException: 로그인이 필요합니다.