Make controller log more details

halo-dev · Dec 8, 2020 · 17b3f85 · 17b3f85
1 parent 5f3e1e8
commit 17b3f85
Show file tree

Hide file tree

Showing 5 changed files with 52 additions and 29 deletions.
diff --git a/src/main/java/run/halo/app/controller/core/CommonController.java b/src/main/java/run/halo/app/controller/core/CommonController.java
@@ -1,6 +1,5 @@
 package run.halo.app.controller.core;
 
-import cn.hutool.extra.servlet.ServletUtil;
 import lombok.extern.slf4j.Slf4j;
 import org.springframework.boot.autoconfigure.web.ErrorProperties;
 import org.springframework.boot.autoconfigure.web.ServerProperties;
@@ -72,12 +71,6 @@ public CommonController(ThemeService themeService,
      */
     @GetMapping
     public String handleError(HttpServletRequest request, HttpServletResponse response, Model model) {
-        log.error("Request URL: [{}], URI: [{}], Request Method: [{}], IP: [{}]",
-                request.getRequestURL(),
-                request.getRequestURI(),
-                request.getMethod(),
-                ServletUtil.getClientIP(request));
-
         handleCustomException(request);
 
         ErrorAttributeOptions options = getErrorAttributeOptions(request);
@@ -168,9 +161,12 @@ private void handleCustomException(@NonNull HttpServletRequest request) {
         Throwable throwable = (Throwable) throwableObject;
 
         if (throwable instanceof NestedServletException) {
-            log.error("Captured an exception", throwable);
+            log.error("Captured an exception: [{}]", throwable.getMessage());
             Throwable rootCause = ((NestedServletException) throwable).getRootCause();
             if (rootCause instanceof AbstractHaloException) {
+                if (!(rootCause instanceof NotFoundException)) {
+                    log.error("Caused by", rootCause);
+                }
                 AbstractHaloException haloException = (AbstractHaloException) rootCause;
                 request.setAttribute("javax.servlet.error.status_code", haloException.getStatus().value());
                 request.setAttribute("javax.servlet.error.exception", rootCause);

diff --git a/src/main/java/run/halo/app/core/ControllerExceptionHandler.java b/src/main/java/run/halo/app/core/ControllerExceptionHandler.java
@@ -140,11 +140,10 @@ private <T> BaseResponse<T> handleBaseException(Throwable t) {
         BaseResponse<T> baseResponse = new BaseResponse<>();
         baseResponse.setMessage(t.getMessage());
 
+        log.error("Captured an exception:", t);
+
         if (log.isDebugEnabled()) {
-            log.error("Captured an exception:", t);
             baseResponse.setDevMessage(ExceptionUtils.getStackTrace(t));
-        } else {
-            log.error("Captured an exception: [{}]", t.getMessage());
         }
 
         return baseResponse;

diff --git a/src/main/java/run/halo/app/core/ControllerLogAop.java b/src/main/java/run/halo/app/core/ControllerLogAop.java
@@ -7,18 +7,21 @@
 import org.aspectj.lang.annotation.Around;
 import org.aspectj.lang.annotation.Aspect;
 import org.aspectj.lang.annotation.Pointcut;
+import org.aspectj.lang.reflect.MethodSignature;
 import org.springframework.core.io.Resource;
 import org.springframework.http.ResponseEntity;
 import org.springframework.lang.NonNull;
 import org.springframework.stereotype.Component;
 import org.springframework.util.Assert;
+import org.springframework.util.StopWatch;
 import org.springframework.web.context.request.RequestContextHolder;
 import org.springframework.web.context.request.ServletRequestAttributes;
 import org.springframework.web.multipart.MultipartFile;
 import run.halo.app.utils.JsonUtils;
 
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
+import java.lang.reflect.Method;
 import java.util.Objects;
 
 /**
@@ -29,12 +32,19 @@
 @Slf4j
 public class ControllerLogAop {
 
-    @Pointcut("execution(*  *..*.*.controller..*.*(..))")
+    @Pointcut("@within(org.springframework.stereotype.Controller)")
     public void controller() {
     }
 
     @Around("controller()")
     public Object controller(ProceedingJoinPoint joinPoint) throws Throwable {
+        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
+        final Method method = signature.getMethod();
+        if (method == null || !log.isDebugEnabled()) {
+            // should never happen
+            return joinPoint.proceed();
+        }
+
         String className = joinPoint.getTarget().getClass().getSimpleName();
         String methodName = joinPoint.getSignature().getName();
         Object[] args = joinPoint.getArgs();
@@ -43,14 +53,25 @@ public Object controller(ProceedingJoinPoint joinPoint) throws Throwable {
         ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
         HttpServletRequest request = Objects.requireNonNull(requestAttributes).getRequest();
 
+        final StopWatch watch = new StopWatch(request.getRequestURI());
+
+        watch.start("PrintRequest");
         printRequestLog(request, className, methodName, args);
-        long start = System.currentTimeMillis();
-        Object returnObj = joinPoint.proceed();
-        printResponseLog(request, className, methodName, returnObj, System.currentTimeMillis() - start);
+        watch.stop();
+
+        watch.start(className + "#" + methodName);
+        final Object returnObj = joinPoint.proceed();
+        watch.stop();
+
+        watch.start("PrintResponse");
+        printResponseLog(request, className, methodName, returnObj);
+        watch.stop();
+        if (log.isDebugEnabled()) {
+            log.debug("Usage:\n{}", watch.prettyPrint());
+        }
         return returnObj;
     }
 
-
     private void printRequestLog(HttpServletRequest request, String clazzName, String methodName, Object[] args) throws JsonProcessingException {
         log.debug("Request URL: [{}], URI: [{}], Request Method: [{}], IP: [{}]",
                 request.getRequestURL(),
@@ -80,32 +101,32 @@ private void printRequestLog(HttpServletRequest request, String clazzName, Strin
         }
     }
 
-    private void printResponseLog(HttpServletRequest request, String className, String methodName, Object returnObj, long usage) throws JsonProcessingException {
+    private void printResponseLog(HttpServletRequest request, String className, String methodName, Object returnObj)
+            throws JsonProcessingException {
         if (log.isDebugEnabled()) {
             String returnData = "";
-
             if (returnObj != null) {
                 if (returnObj instanceof ResponseEntity) {
-                    ResponseEntity responseEntity = (ResponseEntity) returnObj;
+                    ResponseEntity<?> responseEntity = (ResponseEntity<?>) returnObj;
                     if (responseEntity.getBody() instanceof Resource) {
                         returnData = "[ BINARY DATA ]";
-                    } else {
+                    } else if (responseEntity.getBody() != null) {
                         returnData = toString(responseEntity.getBody());
                     }
                 } else {
                     returnData = toString(returnObj);
                 }
 
             }
-            log.debug("{}.{} Response: [{}], usage: [{}]ms", className, methodName, returnData, usage);
+            log.debug("{}.{} Response: [{}]", className, methodName, returnData);
         }
     }
 
     @NonNull
     private String toString(@NonNull Object obj) throws JsonProcessingException {
         Assert.notNull(obj, "Return object must not be null");
 
-        String toString = "";
+        String toString;
         if (obj.getClass().isAssignableFrom(byte[].class) && obj instanceof Resource) {
             toString = "[ BINARY DATA ]";
         } else {

diff --git a/src/main/java/run/halo/app/filter/LogFilter.java b/src/main/java/run/halo/app/filter/LogFilter.java
@@ -20,24 +20,30 @@
  */
 @Slf4j
 @Component
-@Order(Ordered.HIGHEST_PRECEDENCE + 9)
+@Order(Ordered.HIGHEST_PRECEDENCE)
 public class LogFilter extends OncePerRequestFilter {
 
     @Override
     protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
 
-        String remoteAddr = ServletUtil.getClientIP(request);
+        final String remoteAddr = ServletUtil.getClientIP(request);
 
-        log.debug("");
-        log.debug("Starting url: [{}], method: [{}], ip: [{}]", request.getRequestURL(), request.getMethod(), remoteAddr);
+        log.debug("Starting url: [{}], method: [{}], ip: [{}]",
+                request.getRequestURL(),
+                request.getMethod(),
+                remoteAddr);
 
         // Set start time
-        long startTime = System.currentTimeMillis();
+        final long startTime = System.currentTimeMillis();
 
         // Do filter
         filterChain.doFilter(request, response);
 
-        log.debug("Ending   url: [{}], method: [{}], ip: [{}], status: [{}], usage: [{}] ms", request.getRequestURL(), request.getMethod(), remoteAddr, response.getStatus(), System.currentTimeMillis() - startTime);
-        log.debug("");
+        log.debug("Ending   url: [{}], method: [{}], ip: [{}], status: [{}], usage: [{}] ms",
+                request.getRequestURL(),
+                request.getMethod(),
+                remoteAddr,
+                response.getStatus(),
+                System.currentTimeMillis() - startTime);
     }
 }
diff --git a/src/main/resources/application.yaml b/src/main/resources/application.yaml
@@ -47,6 +47,7 @@ management:
 logging:
   level:
     run.halo.app: INFO
+    org.eclipse.jetty.server.HttpChannel: ERROR
   file:
     path: ${user.home}/.halo/logs