[Fix] - log 형식 개선, 간단한 AOP 추가 (#81)

* fix: `Request` `DTO` `@Validation` 현 `GlobalExceptionHandler` 에 맞도록 수정 * fix: `Filter` 에서 에러 발생시 `REQUEST UUID` 보이도록 수정 + fix: 로그 파일에 동일한 `SQL` query 2 번 기록되는 현상 해결 * feat: 간단한 시간 측정 `AOP` 추가
prgrms-web-devcourse-final-project · Dec 4, 2024 · a11fdd8 · a11fdd8
1 parent 7f6b2c3
commit a11fdd8
Show file tree

Hide file tree

Showing 14 changed files with 86 additions and 49 deletions.
diff --git a/src/main/java/com/palettee/archive/controller/dto/request/ArchiveRegisterRequest.java b/src/main/java/com/palettee/archive/controller/dto/request/ArchiveRegisterRequest.java
@@ -1,21 +1,21 @@
 package com.palettee.archive.controller.dto.request;
 
 import jakarta.validation.constraints.NotBlank;
-import java.util.List;
-import org.hibernate.validator.constraints.Length;
+import java.util.*;
+import org.hibernate.validator.constraints.*;
 
 public record ArchiveRegisterRequest(
 
         @NotBlank(message = "제목을 입력해 주세요.")
-        @Length(min = 1, max = 30, message = "최대 30자까지 가능합니다.")
+        @Length(max = 30, message = "최대 30자까지 가능합니다.")
         String title,
 
         @NotBlank(message = "요약을 입력해 주세요.")
-        @Length(min = 1, max = 2500, message = "최대 2500자까지 가능합니다.")
+        @Length(max = 2500, message = "최대 2500자까지 가능합니다.")
         String description,
 
         @NotBlank(message = "내용을 입력해 주세요.")
-        @Length(min = 1, max = 2500, message = "최대 2500자까지 가능합니다.")
+        @Length(max = 2500, message = "최대 2500자까지 가능합니다.")
         String introduction,
 
         @NotBlank(message = "타입을 입력해 주세요.")

diff --git a/src/main/java/com/palettee/archive/controller/dto/request/ArchiveUpdateRequest.java b/src/main/java/com/palettee/archive/controller/dto/request/ArchiveUpdateRequest.java
@@ -1,20 +1,20 @@
 package com.palettee.archive.controller.dto.request;
 
 import jakarta.validation.constraints.NotBlank;
-import java.util.List;
-import org.hibernate.validator.constraints.Length;
+import java.util.*;
+import org.hibernate.validator.constraints.*;
 
 public record ArchiveUpdateRequest(
         @NotBlank(message = "제목을 입력해 주세요.")
-        @Length(min = 1, max = 30, message = "최대 30자까지 가능합니다.")
+        @Length(max = 30, message = "최대 30자까지 가능합니다.")
         String title,
 
         @NotBlank(message = "내용을 입력해 주세요.")
-        @Length(min = 1, max = 2500, message = "최대 2500자까지 가능합니다.")
+        @Length(max = 2500, message = "최대 2500자까지 가능합니다.")
         String description,
 
         @NotBlank(message = "내용을 입력해 주세요.")
-        @Length(min = 1, max = 2500, message = "최대 2500자까지 가능합니다.")
+        @Length(max = 2500, message = "최대 2500자까지 가능합니다.")
         String introduction,
 
         @NotBlank(message = "타입을 입력해 주세요.")

diff --git a/src/main/java/com/palettee/archive/controller/dto/request/CommentUpdateRequest.java b/src/main/java/com/palettee/archive/controller/dto/request/CommentUpdateRequest.java
@@ -1,12 +1,12 @@
 package com.palettee.archive.controller.dto.request;
 
 import jakarta.validation.constraints.NotBlank;
-import org.hibernate.validator.constraints.Length;
+import org.hibernate.validator.constraints.*;
 
 public record CommentUpdateRequest(
 
         @NotBlank(message = "공백은 입력할 수 없습니다.")
-        @Length(min = 1, max = 100, message = "최대 100자까지 가능합니다.")
+        @Length(max = 100, message = "최대 100자까지 가능합니다.")
         String content
 ) {
 }
diff --git a/src/main/java/com/palettee/archive/controller/dto/request/CommentWriteRequest.java b/src/main/java/com/palettee/archive/controller/dto/request/CommentWriteRequest.java
@@ -1,12 +1,12 @@
 package com.palettee.archive.controller.dto.request;
 
 import jakarta.validation.constraints.NotBlank;
-import org.hibernate.validator.constraints.Length;
+import org.hibernate.validator.constraints.*;
 
 public record CommentWriteRequest(
 
         @NotBlank(message = "공백은 입력할 수 없습니다.")
-        @Length(min = 1, max = 100, message = "최대 100자까지 가능합니다.")
+        @Length(max = 100, message = "최대 100자까지 가능합니다.")
         String content
 ) {
 }
diff --git a/src/main/java/com/palettee/global/aop/PerformanceAspect.java b/src/main/java/com/palettee/global/aop/PerformanceAspect.java
@@ -1,14 +1,11 @@
 package com.palettee.global.aop;
 
-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.springframework.stereotype.Component;
-
-import java.lang.reflect.Proxy;
-import java.sql.Connection;
+import java.lang.reflect.*;
+import java.sql.*;
+import lombok.extern.slf4j.*;
+import org.aspectj.lang.*;
+import org.aspectj.lang.annotation.*;
+import org.springframework.stereotype.*;
 
 @Aspect
 @Component
@@ -21,6 +18,10 @@ public class PerformanceAspect {
     public void performancePointcut() {
     }
 
+    @Pointcut("@within(org.springframework.stereotype.Service)")
+    public void serviceExecutionPointcut() {
+    }
+
     @Around("performancePointcut()")
     public Object start(ProceedingJoinPoint joinPoint) throws Throwable {
         final Connection connection = (Connection) joinPoint.proceed();
@@ -32,6 +33,24 @@ public Object start(ProceedingJoinPoint joinPoint) throws Throwable {
         return proxyConnection;
     }
 
+    @Around("serviceExecutionPointcut()")
+    public Object aroundServiceExecution(ProceedingJoinPoint joinPoint) throws Throwable {
+
+        long startTime = System.currentTimeMillis();
+
+        var joinPointSignature = joinPoint.getSignature();
+        String serviceName = joinPointSignature.getDeclaringType().getSimpleName();
+        String methodName = joinPointSignature.getName();
+        String pointcutDesignator = serviceName + "#" + methodName;
+
+        try {
+            return joinPoint.proceed();
+        } finally {
+            long endTime = System.currentTimeMillis();
+            log.debug("[{}] Executed in [{}] ms", pointcutDesignator, endTime - startTime);
+        }
+    }
+
     private Connection getProxyConnection(Connection connection, QueryCounter counter) {
         return (Connection) Proxy.newProxyInstance(
                 getClass().getClassLoader(),

diff --git a/src/main/java/com/palettee/global/logging/MDCLoggingFilter.java b/src/main/java/com/palettee/global/logging/MDCLoggingFilter.java
@@ -29,17 +29,21 @@ protected void doFilterInternal(
         // 요청별 랜덤 uuid 생성 & 저장
         String requestUUID = UUID.randomUUID().toString();
         request.setAttribute("custom-request-uuid", requestUUID);
-        log.info("custom-request-uuid {} has been set to request {} \"{}\"",
-                requestUUID, request.getMethod(), request.getRequestURI());
+        log.info("REQUEST {} \"{}\" earned custom UUID : {}",
+                request.getMethod(), request.getRequestURI(), requestUUID);
 
         try {
 
             this.configureLogDirViaUri(request);
+
+            this.logNewLines();
             log.info("============== REQUEST [{}] START ==============", requestUUID);
             filterChain.doFilter(request, response);
 
         } finally {
             log.info("============== REQUEST [{}] END ==============", requestUUID);
+            this.logNewLines();
+
             MDC.clear();
         }
     }
@@ -53,4 +57,9 @@ private void configureLogDirViaUri(HttpServletRequest request) {
 
         log.info("Domain logging directory has been set to : [{}]", domainType.getDomainLogDir());
     }
+
+    private void logNewLines() {
+        log.info("");
+        log.info("");
+    }
 }
diff --git a/src/main/java/com/palettee/global/security/jwt/filters/JwtExceptionHandlingFilter.java b/src/main/java/com/palettee/global/security/jwt/filters/JwtExceptionHandlingFilter.java
@@ -30,15 +30,16 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
             log.warn("Jwt exception occurred at {}", request.getRequestURI());
 
             ErrorCode err = e.getErrorCode();
-            responseErr(err.getStatus(), err.getReason(), e, response);
+            responseErr(err.getStatus(), err.getReason(), e, response, request);
         } catch (Exception e) {
             log.error("Unexpected exception occurred at {}", request.getRequestURI());
 
-            responseErr(500, e.getMessage(), e, response);
+            responseErr(500, e.getMessage(), e, response, request);
         }
     }
 
-    private void responseErr(int status, String reason, Exception e, HttpServletResponse resp)
+    private void responseErr(int status, String reason, Exception e, HttpServletResponse resp,
+            HttpServletRequest req)
             throws IOException {
         resp.setContentType(MediaType.APPLICATION_JSON_VALUE);
         resp.setCharacterEncoding("UTF-8");
@@ -52,7 +53,9 @@ private void responseErr(int status, String reason, Exception e, HttpServletResp
         objectMapper.registerModule(new JavaTimeModule());
         resp.getWriter().write(objectMapper.writeValueAsString(response));
 
-        log.error("JwtExceptionHandlingFilter handled exception: {}", e.getClass().getSimpleName());
-        log.error("Exception message: {}", e.getMessage());
+        Object requestUUID = req.getAttribute("custom-request-uuid");
+
+        log.error("On REQUEST [{}], JwtExceptionHandlingFilter handled exception : {}",
+                requestUUID, e.getClass().getSimpleName(), e);
     }
 }
diff --git a/src/main/java/com/palettee/global/security/oauth/handler/OAuth2LoginFailureHandler.java b/src/main/java/com/palettee/global/security/oauth/handler/OAuth2LoginFailureHandler.java
@@ -47,7 +47,10 @@ public void onAuthenticationFailure(HttpServletRequest request, HttpServletRespo
         objectMapper.registerModule(new JavaTimeModule());
         response.getWriter().write(objectMapper.writeValueAsString(body));
 
-        log.warn("Handled OAuth2 login failure.");
+        Object requestUUID = request.getAttribute("custom-request-uuid");
+
+        log.warn("Handled OAuth2 login failure on request [{}] : ",
+                requestUUID != null ? requestUUID : "UNKNOWN", exception);
         log.warn("Error status : {}", status);
         log.warn("Error msg : {}", reason);
     }

diff --git a/src/main/java/com/palettee/user/controller/dto/request/users/EditUserInfoRequest.java b/src/main/java/com/palettee/user/controller/dto/request/users/EditUserInfoRequest.java
@@ -8,11 +8,11 @@
 public record EditUserInfoRequest(
 
         @NotBlank(message = "이름을 입력해 주세요.")
-        @Length(min = 1, max = 50, message = "이름은 최대 50자 까지 입니다.")
+        @Length(max = 50, message = "이름은 최대 50자 까지 입니다.")
         String name,
 
         @NotBlank(message = "자기소개를 입력해 주세요.")
-        @Length(min = 1, max = 100, message = "자기소개는 최대 100자 까지 가능합니다.")
+        @Length(max = 100, message = "자기소개는 최대 100자 까지 가능합니다.")
         String briefIntro,
 
         // URL 검증은 필요 없겠지?

diff --git a/src/main/java/com/palettee/user/controller/dto/request/users/RegisterBasicInfoRequest.java b/src/main/java/com/palettee/user/controller/dto/request/users/RegisterBasicInfoRequest.java
@@ -8,11 +8,11 @@
 public record RegisterBasicInfoRequest(
 
         @NotBlank(message = "이름을 입력해 주세요.")
-        @Length(min = 1, max = 50, message = "이름은 최대 50자 까지 입니다.")
+        @Length(max = 50, message = "이름은 최대 50자 까지 입니다.")
         String name,
 
         @NotBlank(message = "자기소개를 입력해 주세요.")
-        @Length(min = 1, max = 100, message = "자기소개는 최대 100자 까지 가능합니다.")
+        @Length(max = 100, message = "자기소개는 최대 100자 까지 가능합니다.")
         String briefIntro,
 
         // URL 검증은 필요 없겠지?

diff --git a/src/main/resources/application-local.yml b/src/main/resources/application-local.yml
@@ -2,7 +2,7 @@ logging:
   level:
     com.palettee: debug
     web: debug
-#    sql: debug
+    sql: debug
 
 spring:
   datasource:
@@ -12,7 +12,6 @@ spring:
     url: jdbc:mysql://localhost:3306/final_project
 
   jpa:
-    show-sql: true
     hibernate:
       ddl-auto: update
     properties:

diff --git a/src/main/resources/logback-appender.xml b/src/main/resources/logback-appender.xml
@@ -1,18 +1,27 @@
 <configuration>
 
+  <!-- spring starter logging 에 있는 로깅 패턴 가져오기 -->
+  <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
+
   <!-- property 에서 값 읽어오기 : 프로필별 로그 저장 위치 -->
   <!-- 로컬에서는 ./logs, EC2 에서는 ~/logs -->
   <springProperty name="LOG_DIR" source="LOG_DIR"/>
 
   <!-- 오늘 날짜, 로그 패턴 -->
   <timestamp key="TODAY" datePattern="yyyy-MM-dd"/>
-  <property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %logger{36} - %msg%n"/>
+
+  <!-- ANSI 적용되는 콘솔용 로그 패턴 -->
+  <property name="LOG_PATTERN_CONSOLE"
+    value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(%5p) %clr(${PID:- }){magenta} %clr([%t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n%wEx"/>
+  <!-- ANSI 코드 없는 그냥 로그 패턴 -->
+  <property name="LOG_PATTERN_PLAIN"
+    value="%d{yyyy-MM-dd HH:mm:ss.SSS} %5p ${PID:- } [%t] %-40.40logger{39} : %m%n%wEx"/>
 
 
   <!-- 콘솔 로그 보이게 하는 appender -->
   <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
     <encoder>
-      <pattern>${LOG_PATTERN}</pattern>
+      <pattern>${LOG_PATTERN_CONSOLE}</pattern>
     </encoder>
   </appender>
 
@@ -28,15 +37,15 @@
       <appender name="FILE-${DOMAIN_LOG_DIR}"
         class="ch.qos.logback.core.rolling.RollingFileAppender">
         <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
-          <fileNamePattern>${LOG_DIR}/${DOMAIN_LOG_DIR}/%d{yyyy-MM-dd}_%i.log
+          <fileNamePattern>${LOG_DIR}/${DOMAIN_LOG_DIR}/${DOMAIN_LOG_DIR}.%d{yyyy-MM-dd}_%i.log
           </fileNamePattern>
           <maxFileSize>10MB</maxFileSize>
           <maxHistory>14</maxHistory>
           <cleanHistoryOnStart>true</cleanHistoryOnStart>
         </rollingPolicy>
 
         <encoder>
-          <pattern>${LOG_PATTERN}</pattern>
+          <pattern>${LOG_PATTERN_PLAIN}</pattern>
         </encoder>
       </appender>
     </sift>
@@ -52,8 +61,7 @@
       <cleanHistoryOnStart>true</cleanHistoryOnStart>
     </rollingPolicy>
     <encoder>
-      <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %logger{36} - %msg%n%ex
-      </pattern> <!-- '%ex' 는 stack trace 도 포함한다 캄 -->
+      <pattern>${LOG_PATTERN_PLAIN}</pattern>
     </encoder>
     <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
       <level>ERROR</level>

diff --git a/src/main/resources/logback-spring.xml b/src/main/resources/logback-spring.xml
@@ -7,6 +7,8 @@
   <!-- ROOT 로그 찍히는거 reference. 솔직히 뭔지 잘 모르겠음. -->
   <root level="INFO">
     <appender-ref ref="CONSOLE"/>
+
+    <!--  SQL debug 둬서 쿼리도 잘 찍힘  -->
     <appender-ref ref="PER-REQUEST"/>
   </root>
 
@@ -17,9 +19,4 @@
   </logger>
 
 
-  <!-- hibernate 쿼리도 도메인별 로그에 저장되도록 추가 -->
-  <logger name="org.hibernate.SQL" level="DEBUG">
-    <appender-ref ref="PER-REQUEST"/>
-  </logger>
-
 </configuration>
diff --git a/src/test/resources/application.yml b/src/test/resources/application.yml
@@ -8,7 +8,6 @@ spring:
   datasource:
     url: jdbc:h2:mem:testdb;MODE=MYSQL;NON_KEYWORDS=USER
   jpa:
-    show-sql: true
     database-platform: org.hibernate.dialect.H2Dialect
     properties:
       hibernate: