GTB-80 [feat] 로깅 구현 #96
Conversation
jwnnoh
requested review from
hoonyworld,
rootTiket and
yechan-kim
and removed request for
hoonyworld and
rootTiket
| Map<String, Object> params = new HashMap<>(); | ||
|
|
There was a problem hiding this comment.
해당 Map 타입은 DTO로 구현이 가능해 보이는데, DTO로 구현하는 것에 대한 의견이 궁금합니다!
아래는 예시 코드입니다!
@Data
class LogDetails {
private String controller;
private String method;
private JSONObject params;
private long logTime;
private String requestUri;
private String httpMethod;
}There was a problem hiding this comment.
DTO라는 좋은 의견을 주셔서 감사합니다 😄
하지만 여러 번 고민 끝에, 다음과 같은 이유로 DTO를 사용하지 않는 것이 가독성 및 유지보수성에서 낫다고 판단하였는데, @yechan-kim 은 어떻게 생각하시나요?
-
메서드 내에서 바로 사용할 변수를 DTO에 매핑하고, 다시 가져오는 로직은 불필요해보입니다.
-
추후 출력할 변수를 변경 시, DTO 및 변수 할당 로직을 추가적으로 변경해야하는 번거로움이 존재합니다.
-
따라서 메서드 내에서 즉시 사용하는 변수는 내부에서 처리하는 것이 맞다는 저의 의견입니다! 😄
There was a problem hiding this comment.
다시 생각해 보니 굳이 DTO로 변경할 필요성이 없을 것 같군요 좋은 의견 감사합니다!
| long end = System.currentTimeMillis(); | ||
| long duration = end - start; |
There was a problem hiding this comment.
해당 부분에 stopwatch()를 도입하려고 하시는 것 같네요. stopwatch()에서는 1ms 보다 더 자세하게 측정을 해주는데, 다른 메서드는 모르겠지만 지금 올려주신 사진을 보면 동작시간이 100ms 정도입니다. 다른 메서드에서도 실행 시간이 10ms이상이라면 전 stopwatch()의 필요성은 없다고 생각합니다.
결론적으로, 실행 시간이 10ms이하인 메서드가 있을 때 도입을 추진하는 것이 좋다고 생각하는데 어떻게 생각하시나요?
There was a problem hiding this comment.
예찬님 의견에 동의하는 바입니다!
현재 로깅의 주 목적이 메서드 및 요청의 기록을 남기기 위함입니다.
따라서 실행 시간을 엄격히 추적하는 것은 아니니, 현재로서는 기존 안을 유지하는 편이 좋을 것 같다는 생각입니다ㅎㅎ
| // Before 어드바이스를 통한 서비스 메서드 시작 로깅 | ||
| @Before(value = "publicMethodsFromService()") | ||
| public void logBeforeService(JoinPoint joinPoint) { | ||
| Object[] args = joinPoint.getArgs(); | ||
| String methodName = joinPoint.getSignature().getDeclaringType().getSimpleName(); | ||
| log.info("⚠️Start: {}() - {}", methodName, Arrays.toString(args)); | ||
| } | ||
|
|
||
| // After 어드바이스를 통한 서비스 메서드 종료 로깅 | ||
| @AfterReturning(value = "publicMethodsFromService()") | ||
| public void logAfterService(JoinPoint joinPoint) { | ||
| String methodName = joinPoint.getSignature().getDeclaringType().getSimpleName(); | ||
| log.info("✅End: {}()", methodName); | ||
| } |
There was a problem hiding this comment.
스크린샷과 PR에 설명에 의하면 정상적인 로직의 로깅 순서는 다음과 같을 것 같습니다.
컨트롤러 Start -> 비즈니스 로직 Start -> 비즈니스 로직 End -> 컨트롤러 End
그리고 비즈니스 로직에서 오류가 발생한다면, Error 로그를 출력하고 있습니다.
그렇다면, 비즈니스 로직의 정상 실행은 컨트롤러 Start -> 컨트롤러 End 로그를 통해서 추론할 수 있다는 생각이 듭니다. 이에 따라 비즈니스 정상 동작 로깅 로직을 삭제해도 좋을 것 같다는 생각이 들었는데, 어떻게 생각하시나요?
There was a problem hiding this comment.
컨트롤러 Start 로그는, Request 요청이 들어왔을 경우 어떤 경로, 방식, 메서드를 통해 요청이 들어왔는지 파악하기 위해 작성하였습니다.
비즈니스 로직에 대한 로깅의 경우, Grafana 및 Pinpoint에서 로그를 확인하기 위해 도입한 부분입니다
따라서 말씀해주신 정상 실행의 경우, 추론보다는 직접 확인하는 편이 좋을 것 같아 유지해도 될 것 같다는 생각입니다!
좋은 의견 감사합니다!🙇
There was a problem hiding this comment.
넵 알겠습니다! 추후에 로깅 방식에 대해서 더 좋은 의견이 생각나면 의견 남기겠습니다.
| @Around("publicMethodsFromService()") | ||
| public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable { | ||
| long start = System.currentTimeMillis(); | ||
| try { | ||
| return joinPoint.proceed(); | ||
| } finally { | ||
| long end = System.currentTimeMillis(); | ||
| long duration = end - start; | ||
|
|
||
| String className = joinPoint.getSignature().getDeclaringType().getSimpleName(); | ||
| String method = joinPoint.getSignature().getName(); | ||
| log.info("{}.{} | time = {}ms", | ||
| className, method, duration); | ||
| } | ||
| } |
There was a problem hiding this comment.
stopwatch 메서드 사용을 고려하신다고 했는데 정확한 시간을 위해서라면 System.nanoTime() 를 이용하는 것도 방법이라고 생각합니다.
기본적으로 간결하고, currentTimeMillis 보다 더 작은 시간단위까지 계산할 수 있습니다
stopwatch는 구간 별로 시간을 측정할 경우가 생기면 도입하는 것이 더 낫다는 생각입니다
추가적으로 굳이 end를 변수로 두기보다
long duration = (System.currentTimeMillis() - start) 나노초로 계산한다면 ..
long duration = (System.nanoTime() - start) / 1_000_000이렇게 두는 편이 개인적으로는 더 보기 편하다고 생각합니다!!
There was a problem hiding this comment.
추가적으로 현재 저희 로깅 목적이 에러를 파악하기 위함 이라면(실행 시간 체크보다도) stopwatch 도입은 조금 미루거나 하지 않는 방향이 목적에 맞다고 생각합니다 :)
There was a problem hiding this comment.
최종적으로 duration 변수만 사용한다면, 굳이 end 변수를 별도로 선언하여 관리할 필요는 없을 것 같습니다!
좋은 의견 감사합니다 😄
nanaoTime()의 경우, 실행 시간을 엄격히 확인하는 것은 아니니, 현재로서는 currentTimeMillis()로 유지하는 편이 좋을 것 같다는 생각입니다ㅎㅎ
There was a problem hiding this comment.
currentTimeMillis 관련해서는 저도 동감합니다! 실행 시간을 엄격히 체크하기보다 적절한 로그 레벨을 파악하는게 우선순위가 되어야할 것 같아요 👍
1. 무슨 이유로 코드를 변경했나요?
AOP 로깅
Note
AOP는 관점 지향 프로그래밍의 약자입니다. 현재 Redisson을 통한 분산락도 해당 방식으로 구현되어 있습니다!
AOP가 궁금하시다면, 해당 링크를 통해 참고해주세요 😄 -> Spring AOP
🤔 적용 방식에 대한 고민
현재 분산 락은 어노테이션 인터페이스를 통해 구현이 되어 있습니다.
로깅은 대부분의 부분에 필요하지만, 어노테이션을 이용한 방식은 휴먼 에러가 존재할 가능성이 무척 증가합니다.
따라서
Aspect를 통해 전역으로 로깅을 구현하였습니다!컨트롤러 <-> 비즈니스 로직 간 로그를 다르게 표현하고 싶어,
PointCut어드바이스를 통해 별도의 메서드로 범위를 각각 지정하였습니다.Before,After어드바이스를 통해 메서드의 시작 및 종료 여부를 표현하였습니다.Around어드바이스를 사용하지 않은 이유는 다음과 같습니다!메서드를 감싸서 성능 이슈를 야기할 수 있는 해당 어드바이스를 사용해야 하는 이유를 못 찾았습니다.
AfterLogging어드바이스를 통해, 커스텀 예외를 잡아 메세지를 출력하도록 설정하였습니다.2. 어떤 위험이나 장애를 발견했나요?
시간 측정 여부
currentTimeMillis()를 통해 시간을 측정하고 있습니다.stopwatch()메서드를 도입해야 하는지에 대한 의문이 존재해, 더 나은 의견을 여쭙고 싶습니다!3. 관련 스크린샷을 첨부해주세요.
4. 완료 사항
이슈 번호
close #95
5. 추가 사항
main브랜치로 머지하여 릴리즈 진행 할 예정입니다.