실전 프로젝트 2 - 로깅, log4j2
항상 프로젝트를 진행하면서 로그에 대한 아쉬움이 있었다. 특정 오류가 발생될 것이라고 예상되는 지점에만 로그를 찍기에는 예상치 못한 오류가 발생하여 이를 빠르게 알아차릴 수 없었고, 그렇다고 모든 곳에 로그를 찍기에는 코드 자체의 복잡성도 증가하고 시간이 부족하다고 생각됐다. 마침 스프링 AOP에 관한 강의를 들으면서 해당 로그추적 소스가 있었고, AOP학습과 함께 직접 이번 프로젝트에 적용시켜보고 싶다는 생각이 들었다. 최대한 코드 자체를 복사 붙여넣기하기 보다는 AOP에 대한 이해와 로깅 코드를 구현 및 리팩토링 해보는 방향성을 세웠다.
팀원들의 요구는 총 4가지였다
1. 같은 요청임을 확인할 수 있는 로그
2. 메서드가 호출된 메서드들을 기록하여 메서드의 depth를 확인할 수 있는 로그
3. 결제, 포인트충전 부분에서 해당 정보들을 확인할 수 있는 로그
4. 해당 로그들을 파일로 분리하여 따로 관리할 수 있게끔 할 것
구체적인 로깅 트레이스 코드는 강의에서 제공하는 방식을 직접 타이핑하여 작성해봤다. 다만 개인적으로 수정하고 싶은 부분들이 몇 개 있었는데 팀 코드 컨벤션에 정한 규칙대로 else 문을 사용하지 않거나, 삼항연산자를 제거하고 새롭게 작성하는 부분들이었다.
private void syncTraceId() {
TraceId traceId = traceIdHolder.get();
if (traceId == null) {
traceIdHolder.set(new TraceId());
}
if (traceId != null) {
traceIdHolder.set(traceId.createNextId());
}
} private void releaseTraceId() {
TraceId traceId = traceIdHolder.get();
traceIdHolder.set(traceId.createPreviousId());
if (traceId.isFirstLevel()) {
traceIdHolder.remove();
}
} private static String addSpace(String prefix, int level) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level; i++) {
if (i != level - 1) {
sb.append("| ");
}
if (i == level - 1) {
sb.append("|" + prefix);
}
}
return sb.toString();
}최대한 얼리리턴의 방식을 차용하면서 팀에서 정한 코드컨벤션을 지키고자 노력하는 기본 로그 트레이스 로직을 만들었다. 해당 코드들을 통해 팀원들이 요구하는 1,2번을 만족시킬 수 있었다.
@Pointcut("execution(* challenge.competer.domain..*(..))")
public void all() {}
@Pointcut("execution(* challenge.competer.domain.member.controller.MemberController.addPoint(..))")
public void point() {}
@Pointcut("execution(* challenge.competer.domain.transaction.controller.TransactionController.*(..))")
public void transaction() {}3번째 팀원들의 요구사항인 결제,포인트와 관련된 조건을 @Pointcut으로 작성하였다. 본격적으로 AOP를 활용한 곳인데 확실히 공통관심사인 로깅작업을 따로 빼내어 특정 부분에 적용할 수 있는 AOP는 정말 놀라운 기능인 것 같다. 스프링을 공부하면서 항상 느끼지만 유독 '와 이것까지 된다고?' 느꼈던 게 몇 개 있는데 그 중 대표적인 게 DI, 3Layer아키텍처, JPA(특히 스프링 데이터 JPA), Querydsl 정도 뽑을 수 있는데 AOP도 이 리스트에 합류할 수 있는 정도의 놀라움이었다.
@Before("point() && args(pointDto,..)")
public void logAddPoint(JoinPoint joinPoint, RequestMemberPointDto pointDto) {
log.info("[{}] point = {}", joinPoint.getSignature().getName(), pointDto.getPoint());
}
@Before("transaction() && args(productId, transactionDto,..)")
public void logTransaction(JoinPoint joinPoint, Long productId, RequestTransactionDto transactionDto) {
log.info("[{}] productId = {}, price = {}" , joinPoint.getSignature().getName(), productId, transactionDto.getPrice());
}
@Around("all()")
public Object logAll(ProceedingJoinPoint joinPoint) throws Throwable {
TraceStatus status = null;
try {
String message = joinPoint.getSignature().toShortString();
status = logTrace.begin(message);
Object result = joinPoint.proceed();
logTrace.end(status);
return result;
} catch (Exception e) {
logTrace.exception(status, e);
throw e;
}
}해당 Pointcut이 지정하는 특정 부분들을 바탕으로 실행할 공통 로직인 Advice. @Around를 통해 1,2번의 요구사항을 반영하였고, 포인트충전과 결제에 대한 사전 정보가 필요할 것 같아 @Before를 우선은 활용했다. 해당 부분에 대해서 추가적인 피드백이나 요구사항이 생긴다면 변경할 예정이지만 일단은 MVP 구현 주차에서 @Before를 사용하는 게 요청이 제대로 갔는지 확인하는 데 용이할 거 같아 해당 애너테이션으로 결정하였다.
이쯤에서 logback과 log4j2를 알게 되었다. 파일로 관리하고 싶다는 4번 요구사항에 맞게 xml 설정 파일에 대한 자료를 찾는 중 logback에 비해 log4j2가 비교적 성능적으로 우수한 면을 가지고 있다는 글을 보았다. 무엇보다 대용량 트래픽 처리를 염두에 두고 있는 이번 프로젝트에서 멀티 쓰레드 환경에서 우수한 성능을 보여주는 log4j2는 충분히 고려해볼만 하다고 생각했다.
log4j2의 장점
비동기 로깅 - 로깅을 처리하는 별도의 스레드를 사용하여 애플리케이션이 로깅이 완료될 때까지 기다리지 않고 실행을 지속. 이는 특히 고처리량 환경에서 애플리케이션 성능을 개선하는 데 도움이 됩니다.
가비지 생성 최소화 - Log4j 2는 로깅 중 임시 객체 생성을 최소화하려고 노력하여 가비지 컬렉션 부담을 줄이고 고처리량 시나리오에서 애플리케이션 성능을 향상
따라서 log4j2를 사용하기 위해 logback 디폴트인 기존 스프링 부트의 logging 의존성을 제거해주고 log4j2를 추가하였다.
configurations {
all {
exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
}
compileOnly {
extendsFrom annotationProcessor
}
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-log4j2'
...
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="info" monitorInterval="5">
<!--공통 속성 설정 -->
<Properties>
<Property name="logFileName">BasicLog</Property>
<Property name="logFileName-AOP">AOPLog</Property>
<Property name="BASE_DIR">./logs</Property>
<Property name="consoleLayout">[%d{yyyy-MM-dd HH:mm:ss}] [%-5p] [%c{1}:%L] - %m%n</Property>
<Property name="fileLayout">%d [%t] %-5level - %m%n</Property>
</Properties>
<!-- Log Appender 설정 -->
<Appenders>
<!-- console 패턴정의 -->
<Console name="console" target="SYSTEM_OUT">
<PatternLayout pattern="${consoleLayout}" />
</Console>
<!--파일 패턴 및 정책 정의 -->
<!-- 로그를 추가할 파일 Appender -->
<RollingFile name="File"
fileName="${BASE_DIR}/${logFileName}.log"
filePattern="${BASE_DIR}/${logFileName}.%d{yyyy-MM-dd-hh}.log">
<PatternLayout pattern="${fileLayout}" />
<Policies>
<TimeBasedTriggeringPolicy modulate="true" interval="10" />
</Policies>
<DefaultRolloverStrategy max="10" fileIndex="min">
<Delete basePath="${BASE_DIR}" maxDepth="3">
<IfLastModified age="10d" />
</Delete>
</DefaultRolloverStrategy>
</RollingFile>
<!-- "AOP"를 통해 로그를 추가할 파일 Appender -->
<RollingFile name="AOPFile"
fileName="${BASE_DIR}/${logFileName-AOP}.log"
filePattern="${BASE_DIR}/${logFileName-AOP}.%d{yyyy-MM-dd-hh}.log">
<PatternLayout pattern="${fileLayout}" />
<Policies>
<TimeBasedTriggeringPolicy modulate="true" interval="24" />
</Policies>
<DefaultRolloverStrategy max="10" fileIndex="min">
<Delete basePath="${BASE_DIR}" maxDepth="3">
<IfLastModified age="10d" />
</Delete>
</DefaultRolloverStrategy>
</RollingFile>
<!-- "warn" 레벨 로그를 추가할 파일 Appender -->
<RollingFile name="daily_errorFile"
fileName="${BASE_DIR}/error/error.log"
filePattern="${BASE_DIR}/error/error.%d{yyyy-MM-dd}.log">
<PatternLayout pattern="${fileLayout}" />
<LevelRangeFilter minLevel="error" maxLevel="error" onMatch="ACCEPT" onMismatch="DENY"/>
<Policies>
<SizeBasedTriggeringPolicy size="20 MB" />
</Policies>
<DefaultRolloverstrategy>
<Delete basePath="${BASE_DIR}" maxDepth="3">
<IfLastModified age="10d" />
</Delete>
</DefaultRolloverstrategy>
</RollingFile>
</Appenders>
<!--로그 설정-->
<Loggers>
<!-- 스프링 프레임워크에서 실행될 때 로거 설정 -->
<logger name="org.springframework" level="info" additivity="false" >
<AppenderRef ref="console" />
<AppenderRef ref="File" />
</logger>
<!-- "AOP"를 적용할 패키지 또는 클래스에 대한 로거 설정 -->
<logger name="challenge.competer.global.log.LogAspect" level="debug" additivity="false">
<AppenderRef ref="console" />
<AppenderRef ref="AOPFile" />
</logger>
<logger name="challenge.competer.global.log.LogTraceImpl" level="debug" additivity="false">
<AppenderRef ref="console" />
<AppenderRef ref="AOPFile" />
</logger>
<!-- "error" 레벨 로거 설정 -->
<logger name="challenge.competer.domain" level="error" additivity="true" >
<AppenderRef ref="daily_errorFile" />
</logger>
<!-- ROOT logger-->
<!-- off, fatal, error, warn, info, debug, trace, all -->
<Root level="error" additivity="false">
<AppenderRef ref="File"/>
<AppenderRef ref="AOPFile" />
<AppenderRef ref="console" />
</Root>
</Loggers>
</Configuration>log4j2.xml - 로그 관련 설정
해당 xml 파일의 부분들에 대한 자료를 찾는 게 쉽지 않아서 꽤 어려움을 겪었던 xml 설정이었던 것 같다. 심지어 콘솔에는 로그가 제대로 찍히지 않아서 어떤 게 문제인지 고민하느라 2시간 가까이 씨름하기도 했다. 해당 오류는 Root logger가 제대로 설정이 안 되어 있어서 발생하는 오류였고 이를 수정한 뒤에는 정상적으로 로그가 찍히는 것을 확인할 수 있었다.
@Test
@DisplayName("로깅 내역 확인")
void logging() {
TraceStatus traceStatus1 = logTrace.begin("Controller.read");
TraceStatus traceStatus2 = logTrace.begin("Service.read");
TraceStatus traceStatus3 = logTrace.begin("Repository.read");
logTrace.end(traceStatus3);
logTrace.end(traceStatus2);
logTrace.end(traceStatus1);
TraceStatus traceStatus4 = logTrace.begin("Controller.read");
TraceStatus traceStatus5 = logTrace.begin("Service.read");
TraceStatus traceStatus6 = logTrace.begin("Repository.read");
logTrace.end(traceStatus6);
logTrace.end(traceStatus5);
logTrace.end(traceStatus4);
}
[Test worker] INFO - [48665781] Controller.read
[Test worker] INFO - [48665781] |-->Service.read
[Test worker] INFO - [48665781] | |-->Repository.read
[Test worker] INFO - [48665781] | |<--Repository.read time=1
[Test worker] INFO - [48665781] |<--Service.read time=3
[Test worker] INFO - [48665781] Controller.read time=19
[Test worker] INFO - [9623d406] Controller.read
[Test worker] INFO - [9623d406] |-->Service.read
[Test worker] INFO - [9623d406] | |-->Repository.read
[Test worker] INFO - [9623d406] | |<--Repository.read time=1
[Test worker] INFO - [9623d406] |<--Service.read time=3
[Test worker] INFO - [9623d406] Controller.read time=5<테스트 로그>
여차저차 로깅에 대한 구현을 이틀동안 시도했던 거 같다. 마저 남은 AOP 공부를 좀 더 진행하고 실제 API에 따른 코드 작성을 시작해야겠다. 빠르게 MVP 구현을 완료하고 팀에서 목표하는 MSA로의 변환을 다루고 싶다.