feat(log): add logging filter & AOP module (#94)

* feat(member): add DynamicUpdate to Member Entity for optimize query * test: change test type to DynamicTest * chore(log): add log4j2 dependency & configuration file * cherry-pick: fix: Add exception handler and EndPointcheckfilter to security (#93) * feat(log): add module counting query invocation in one http request * feat(log): add filter logging request and response information * feat(log): add logging filter to spring security * feat(log): add memberId to MDC after authenticated * feat(log): add Controller, Service Log AOP module * refactor(log): change log format * style: change error message and resolver logic * refactor: change Aspect getMemberId() logic * fix: fix compile error in Integration Test * test: combine Test environment to reduce rising Spring Boot Server * refactor(log): change log framework (#97) * chore: change log framework log4j2 to logback * refactor: change log module log4j2 to slf4j --------- Co-authored-by: KAispread <[email protected]> --------- Co-authored-by: KAispread <[email protected]> Co-authored-by: chaerim <[email protected]>
SWM-E2I · Aug 14, 2023 · cff590f · cff590f
1 parent 9be28c5
commit cff590f
Show file tree

Hide file tree

Showing 23 changed files with 640 additions and 96 deletions.
diff --git a/src/main/java/com/e2i/wemeet/config/log/LogConfig.java b/src/main/java/com/e2i/wemeet/config/log/LogConfig.java
@@ -0,0 +1,42 @@
+package com.e2i.wemeet.config.log;
+
+import com.e2i.wemeet.config.log.aspect.ControllerLogAspect;
+import com.e2i.wemeet.config.log.aspect.QueryCounterAspect;
+import com.e2i.wemeet.config.log.aspect.ServiceLogAspect;
+import com.e2i.wemeet.config.log.module.QueryCounter;
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+import org.springframework.util.StopWatch;
+import org.springframework.web.context.annotation.RequestScope;
+
+@Configuration
+public class LogConfig {
+
+    @RequestScope
+    @Bean
+    public StopWatch apiWatch() {
+        return new StopWatch();
+    }
+
+    @RequestScope
+    @Bean
+    public QueryCounter queryCounter() {
+        return new QueryCounter();
+    }
+
+    @Bean
+    public QueryCounterAspect queryCounterAspect() {
+        return new QueryCounterAspect(queryCounter());
+    }
+
+    @Bean
+    public ControllerLogAspect logControllerAspect() {
+        return new ControllerLogAspect();
+    }
+
+    @Bean
+    public ServiceLogAspect logServiceAspect() {
+        return new ServiceLogAspect();
+    }
+
+}
diff --git a/src/main/java/com/e2i/wemeet/config/log/LogFilter.java b/src/main/java/com/e2i/wemeet/config/log/LogFilter.java
@@ -0,0 +1,129 @@
+package com.e2i.wemeet.config.log;
+
+import static com.e2i.wemeet.config.log.MdcKey.CORRELATION_ID;
+import static com.e2i.wemeet.config.log.MdcKey.MEMBER_ID;
+
+import com.e2i.wemeet.config.log.module.QueryCounter;
+import jakarta.servlet.FilterChain;
+import jakarta.servlet.ServletException;
+import jakarta.servlet.http.HttpServletRequest;
+import jakarta.servlet.http.HttpServletResponse;
+import java.io.IOException;
+import java.util.UUID;
+import lombok.extern.slf4j.Slf4j;
+import org.slf4j.MDC;
+import org.springframework.stereotype.Component;
+import org.springframework.util.StopWatch;
+import org.springframework.util.StringUtils;
+import org.springframework.web.filter.OncePerRequestFilter;
+import org.springframework.web.util.ContentCachingRequestWrapper;
+import org.springframework.web.util.ContentCachingResponseWrapper;
+
+@Slf4j
+@Component
+public class LogFilter extends OncePerRequestFilter {
+
+    private static final String REQUEST_LOG_FORMAT = "REQUEST:: HTTP_METHOD: {}, URL: {}, AGENT: {}, BODY: {}";
+    private static final String RESPONSE_LOG_FORMAT = "RESPONSE:: HTTP_METHOD= {}, URL= {}, STATUS_CODE= {}, QUERY_COUNT= {}, TIME_TAKEN= {}ms, MEMBER_ID= {}, BODY= {}";
+    private static final String QUERY_COUNT_WARNING_LOG_FORMAT = "WARN QUERY EXECUTION TIME:: {}";
+
+    private static final int QUERY_COUNT_WARNING_STANDARD = 10;
+    private static final String NO_REQUEST_BODY = "none";
+    private static final String NOT_AUTHENTICATED = "none";
+
+    private final StopWatch apiWatch;
+    private final QueryCounter queryCounter;
+
+    public LogFilter(final StopWatch apiWatch, final QueryCounter queryCounter) {
+        this.apiWatch = apiWatch;
+        this.queryCounter = queryCounter;
+    }
+
+    @Override
+    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
+        throws ServletException, IOException {
+        final ContentCachingRequestWrapper requestWrapper = new ContentCachingRequestWrapper(request);
+        final ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(response);
+
+        // Before request
+        addCorrelationIdToMdc();
+
+        apiWatch.start();
+        filterChain.doFilter(requestWrapper, responseWrapper);
+        apiWatch.stop();
+
+        // After request
+        loggingRequest(requestWrapper);
+        loggingResponse(requestWrapper, responseWrapper);
+        notifyQueryCountWarning();
+
+        MDC.clear();
+        responseWrapper.copyBodyToResponse();
+    }
+
+    // 쿼리 수행 개수가 QUERY_COUNT_WARNING_STANDARD 이상일 경우, 로그를 남긴다.
+    private void notifyQueryCountWarning() {
+        if (getQueryCount() >= QUERY_COUNT_WARNING_STANDARD) {
+            log.warn(QUERY_COUNT_WARNING_LOG_FORMAT, getQueryCount());
+        }
+    }
+
+    // Request Logging
+    private void loggingRequest(final ContentCachingRequestWrapper requestWrapper) {
+        final String method = requestWrapper.getMethod();
+        final String url = getUrlWithQueryParameters(requestWrapper);
+        final String agent = requestWrapper.getHeader("User-Agent");
+        final String body = new String(requestWrapper.getContentAsByteArray());
+
+        if (!StringUtils.hasText(body)) {
+            log.info(REQUEST_LOG_FORMAT, method, url, agent, NO_REQUEST_BODY);
+            return;
+        }
+
+        log.info(REQUEST_LOG_FORMAT, method, url, agent, body);
+    }
+
+    // Response Logging
+    private void loggingResponse(final ContentCachingRequestWrapper requestWrapper,
+        final ContentCachingResponseWrapper responseWrapper) {
+        final String method = requestWrapper.getMethod();
+        final String url = getUrlWithQueryParameters(requestWrapper);
+        final int statusCode = responseWrapper.getStatus();
+
+        final int queryCount = getQueryCount();
+        final long timeTaken = apiWatch.getTotalTimeMillis();
+        final String memberId = getMemberId();
+        final String body = new String(responseWrapper.getContentAsByteArray());
+
+        log.info(RESPONSE_LOG_FORMAT, method, url, statusCode, queryCount, timeTaken, memberId, body);
+    }
+
+    // MemberId를 가져온다. (memberId가 없을 경우, 인증된 사용자가 아니므로 NOT_AUTHENTICATED를 반환한다.)
+    private String getMemberId() {
+        String memberId = MDC.get(MEMBER_ID.getKey());
+        if (!StringUtils.hasText(memberId)) {
+            return NOT_AUTHENTICATED;
+        }
+        return memberId;
+    }
+
+    // API 요청에서 수행된 쿼리의 개수를 가져온다.
+    private int getQueryCount() {
+        return queryCounter.getQueryCount();
+    }
+
+    // MDC에 correlationId를 추가한다.
+    private void addCorrelationIdToMdc() {
+        MDC.put(CORRELATION_ID.getKey(), String.valueOf(UUID.randomUUID()));
+    }
+
+    // 쿼리 파라미터를 포함한 URL을 가져온다.
+    private String getUrlWithQueryParameters(final ContentCachingRequestWrapper requestWrapper) {
+        if (!StringUtils.hasText(requestWrapper.getQueryString())) {
+            return requestWrapper.getRequestURI();
+        }
+        return requestWrapper.getRequestURI() + "?" + requestWrapper.getQueryString();
+    }
+
+
+}
diff --git a/src/main/java/com/e2i/wemeet/config/log/MdcKey.java b/src/main/java/com/e2i/wemeet/config/log/MdcKey.java
@@ -0,0 +1,16 @@
+package com.e2i.wemeet.config.log;
+
+import lombok.Getter;
+
+@Getter
+public enum MdcKey {
+    CORRELATION_ID("correlationId"),
+    MEMBER_ID("memberId"),
+    ;
+
+    private final String key;
+
+    MdcKey(String key) {
+        this.key = key;
+    }
+}
diff --git a/src/main/java/com/e2i/wemeet/config/log/aspect/ControllerLogAspect.java b/src/main/java/com/e2i/wemeet/config/log/aspect/ControllerLogAspect.java
@@ -0,0 +1,60 @@
+package com.e2i.wemeet.config.log.aspect;
+
+import com.e2i.wemeet.config.log.MdcKey;
+import java.util.HashMap;
+import java.util.Map;
+import lombok.extern.slf4j.Slf4j;
+import org.aspectj.lang.JoinPoint;
+import org.aspectj.lang.ProceedingJoinPoint;
+import org.aspectj.lang.annotation.Around;
+import org.aspectj.lang.annotation.Aspect;
+import org.aspectj.lang.reflect.MethodSignature;
+import org.slf4j.MDC;
+import org.springframework.util.StringUtils;
+
+@Slf4j
+@Aspect
+public class ControllerLogAspect {
+
+    private static final String CONTROLLER_LOG_FORMAT_BEFORE_PROCEED = "[CONTROLLER-START]:: MEMBER_ID: {}, CLASS: {}, METHOD: {}, PARAMS: {}";
+    private static final String CONTROLLER_LOG_FORMAT_AFTER_PROCEED = "[CONTROLLER-END]:: MEMBER_ID: {}, CLASS: {}, METHOD: {}, RETURN_TYPE: {}, RETURN_VALUE: {}";
+    private static final String NOT_AUTHENTICATED = "none";
+
+    @Around("execution(* com.e2i.wemeet.controller..*.*(..))")
+    public Object verify(ProceedingJoinPoint joinPoint) throws Throwable {
+        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
+
+        String className = joinPoint.getTarget().getClass().getSimpleName();
+        String methodName = signature.getMethod().getName();
+        Map<String, Object> parameters = getParameters(joinPoint, signature);
+        String memberId = getMemberId();
+
+        log.info(CONTROLLER_LOG_FORMAT_BEFORE_PROCEED, memberId, className, methodName, parameters);
+        Object proceed = joinPoint.proceed();
+
+        log.info(CONTROLLER_LOG_FORMAT_AFTER_PROCEED, memberId, className, methodName, signature.getReturnType().getSimpleName(), proceed);
+
+        return proceed;
+    }
+
+    private String getMemberId() {
+        String memberId = MDC.get(MdcKey.MEMBER_ID.getKey());
+        if (!StringUtils.hasText(memberId)) {
+            return NOT_AUTHENTICATED;
+        }
+        return memberId;
+    }
+
+    private Map<String, Object> getParameters(JoinPoint joinPoint, MethodSignature signature) {
+        Map<String, Object> parameterMap = new HashMap<>();
+
+        String[] parameterNames = signature.getParameterNames();
+        Object[] parameters = joinPoint.getArgs();
+
+        for (int i = 0; i < parameterNames.length; i++) {
+            parameterMap.put(parameterNames[i], parameters[i]);
+        }
+        return parameterMap;
+    }
+
+}
diff --git a/src/main/java/com/e2i/wemeet/config/log/aspect/QueryCounterAspect.java b/src/main/java/com/e2i/wemeet/config/log/aspect/QueryCounterAspect.java
@@ -0,0 +1,30 @@
+package com.e2i.wemeet.config.log.aspect;
+
+import com.e2i.wemeet.config.log.module.ConnectionInvocationHandler;
+import com.e2i.wemeet.config.log.module.QueryCounter;
+import java.lang.reflect.Proxy;
+import lombok.RequiredArgsConstructor;
+import org.aspectj.lang.ProceedingJoinPoint;
+import org.aspectj.lang.annotation.Around;
+import org.aspectj.lang.annotation.Aspect;
+
+@RequiredArgsConstructor
+@Aspect
+public class QueryCounterAspect {
+
+    private final QueryCounter apiQueryCounter;
+
+    /*
+     * database 와 connection 이 일어날 때마다 queryCount를 늘림
+     * */
+    @Around("execution(* javax.sql.DataSource.getConnection())")
+    public Object getConnection(final ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
+        final Object connection = proceedingJoinPoint.proceed();
+        return Proxy.newProxyInstance(
+            connection.getClass().getClassLoader(),
+            connection.getClass().getInterfaces(),
+            new ConnectionInvocationHandler(connection, apiQueryCounter)
+        );
+    }
+
+}
diff --git a/src/main/java/com/e2i/wemeet/config/log/aspect/ServiceLogAspect.java b/src/main/java/com/e2i/wemeet/config/log/aspect/ServiceLogAspect.java
@@ -0,0 +1,58 @@
+package com.e2i.wemeet.config.log.aspect;
+
+import com.e2i.wemeet.config.log.MdcKey;
+import java.util.HashMap;
+import java.util.Map;
+import lombok.extern.slf4j.Slf4j;
+import org.aspectj.lang.JoinPoint;
+import org.aspectj.lang.ProceedingJoinPoint;
+import org.aspectj.lang.annotation.Around;
+import org.aspectj.lang.annotation.Aspect;
+import org.aspectj.lang.reflect.MethodSignature;
+import org.slf4j.MDC;
+import org.springframework.util.StringUtils;
+
+@Slf4j
+@Aspect
+public class ServiceLogAspect {
+
+    private static final String SERVICE_LOG_FORMAT_BEFORE_PROCEED = "[SERVICE-START] :: MEMBER_ID: {}, CLASS: {}, METHOD: {}, PARAMS: {}";
+    private static final String SERVICE_LOG_FORMAT_AFTER_PROCEED = "[SERVICE-END] :: MEMBER_ID: {}, CLASS: {}, METHOD: {}, RETURN_TYPE: {}, RETURN_VALUE: {}";
+    private static final String NOT_AUTHENTICATED = "none";
+
+    @Around("execution(* com.e2i.wemeet.service..*.*(..))")
+    public Object verify(ProceedingJoinPoint joinPoint) throws Throwable {
+        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
+
+        String className = joinPoint.getTarget().getClass().getSimpleName();
+        String methodName = signature.getMethod().getName();
+        String memberId = getMemberId();
+
+        log.info(SERVICE_LOG_FORMAT_BEFORE_PROCEED, memberId, className, methodName, getParameters(joinPoint, signature));
+        Object proceed = joinPoint.proceed();
+
+        log.info(SERVICE_LOG_FORMAT_AFTER_PROCEED, memberId, className, methodName, signature.getReturnType().getSimpleName(), proceed);
+        return proceed;
+    }
+
+    private String getMemberId() {
+        String memberId = MDC.get(MdcKey.MEMBER_ID.getKey());
+        if (!StringUtils.hasText(memberId)) {
+            return NOT_AUTHENTICATED;
+        }
+        return memberId;
+    }
+
+    private Map<String, Object> getParameters(JoinPoint joinPoint, MethodSignature signature) {
+        Map<String, Object> parameterMap = new HashMap<>();
+
+        String[] parameterNames = signature.getParameterNames();
+        Object[] parameters = joinPoint.getArgs();
+
+        for (int i = 0; i < parameterNames.length; i++) {
+            parameterMap.put(parameterNames[i], parameters[i]);
+        }
+        return parameterMap;
+    }
+
+}
diff --git a/src/main/java/com/e2i/wemeet/config/log/module/ConnectionInvocationHandler.java b/src/main/java/com/e2i/wemeet/config/log/module/ConnectionInvocationHandler.java
@@ -0,0 +1,32 @@
+package com.e2i.wemeet.config.log.module;
+
+import java.lang.reflect.InvocationHandler;
+import java.lang.reflect.Method;
+import java.lang.reflect.Proxy;
+
+/*
+ * Jdbc Connection 을 받아 오는 동적 프록시 객체
+ * */
+public class ConnectionInvocationHandler implements InvocationHandler {
+
+    private final Object connection;
+    private final QueryCounter queryCounter;
+
+    public ConnectionInvocationHandler(Object connection, QueryCounter queryCounter) {
+        this.connection = connection;
+        this.queryCounter = queryCounter;
+    }
+
+    @Override
+    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
+        final Object result = method.invoke(connection, args);
+        if (method.getName().equals("prepareStatement")) {
+            return Proxy.newProxyInstance(
+                result.getClass().getClassLoader(),
+                result.getClass().getInterfaces(),
+                new PreparedStatementInvocationHandler(result, queryCounter)
+            );
+        }
+        return result;
+    }
+}