Springboot @Aspect注解式日志统一管理

Springboot @Aspect注解式日志统一管理

前言

本文开始之前，需要对Springboot（http://projects.spring.io/spring-boot/）有基础的了解。：）

先让我们简单回顾Spring AOP的相关的知识：

(Tips：Spring AOP的相关的知识来源于该博文http://www.cnblogs.com/xrq730/p/4919025.html，更多AOP详细介绍请到此查看)

AOP

AOP（Aspect Oriented Programming），即面向切面编程，可以说是OOP（Object Oriented Programming，面向对象编程）的补充和完善。OOP引入封装、继承、多态等概念来建立一种对象层次结构，用于模拟公共行为的一个集合。不过OOP允许开发者定义纵向的关系，但并不适合定义横向的关系，例如日志功能。日志代码往往横向地散布在所有对象层次中，而与它对应的对象的核心功能毫无关系对于其他类型的代码，如安全性、异常处理和透明的持续性也都是如此，这种散布在各处的无关的代码被称为横切（cross cutting），在OOP设计中，它导致了大量代码的重复，而不利于各个模块的重用。

AOP技术恰恰相反，它利用一种称为"横切"的技术，剖解开封装的对象内部，并将那些影响了多个类的公共行为封装到一个可重用模块，并将其命名为"Aspect"，即切面。所谓"切面"，简单说就是那些与业务无关，却为业务模块所共同调用的逻辑或责任封装起来，便于减少系统的重复代码，降低模块之间的耦合度，并有利于未来的可操作性和可维护性。

使用"横切"技术，AOP把软件系统分为两个部分：核心关注点和横切关注点。业务处理的主要流程是核心关注点，与之关系不大的部分是横切关注点。横切关注点的一个特点是，他们经常发生在核心关注点的多处，而各处基本相似，比如权限认证、日志、事物。AOP的作用在于分离系统中的各种关注点，将核心关注点和横切关注点分离开来。

AOP核心概念

1、横切关注点

对哪些方法进行拦截，拦截后怎么处理，这些关注点称之为横切关注点

2、切面（aspect）

类是对物体特征的抽象，切面就是对横切关注点的抽象

3、连接点（joinpoint）

被拦截到的点，因为Spring只支持方法类型的连接点，所以在Spring中连接点指的就是被拦截到的方法，实际上连接点还可以是字段或者构造器

4、切入点（pointcut）

对连接点进行拦截的定义

5、通知（advice）

所谓通知指的就是指拦截到连接点之后要执行的代码，通知分为前置、后置、异常、最终、环绕通知五类

6、目标对象

代理的目标对象

7、织入（weave）

将切面应用到目标对象并导致代理对象创建的过程

8、引入（introduction）

在不修改代码的前提下，引入可以在运行期为类动态地添加一些方法或字段

正文

完整代码：

import com.alibaba.fastjson.JSON;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;
import java.util.Enumeration;

/**
 * @author tan.dg
 * @date 2018/4/19 15:00
 */
@Aspect
@Order(1)
@Component
public class HttpLogAspect {

    private Logger LOG = LoggerFactory.getLogger(getClass());

    ThreadLocal<Long> startTime = new ThreadLocal();

    @Pointcut("execution(public * com.tandg.plus.web..*.*(..))")
    public void httpLog() {}

    @Before("httpLog()")
    public void runBefore(JoinPoint joinPoint) {
        startTime.set(System.currentTimeMillis());
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        LOG.info("URL : {}", request.getRequestURL()+" ["+request.getMethod()+"]");
        LOG.info("IP : {}", request.getRemoteAddr());
        Enumeration<String> headerNames = request.getHeaderNames();
        while(headerNames.hasMoreElements()) {
            String nextElement = headerNames.nextElement();
            LOG.info(nextElement.toUpperCase() + " : {}", request.getHeader(nextElement));
        }
        LOG.info("CLASS_METHOD : {}", joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());
        LOG.info("PARAM : {}", null != request.getQueryString() ? JSON.toJSONString(request.getQueryString().split("&")) : "EMPTY");
    }

    @AfterReturning(returning = "response", pointcut = "httpLog()")
    public void runAfterReturning(Object response) {
        LOG.info("RESPONSE : {}", JSON.toJSONString(response));
        LOG.info("SPEND TIME : {}", (System.currentTimeMillis() - startTime.get()) + "ms");
    }
}

logback.xml配置：

<?xml version="1.0" encoding="UTF-8"?>
<configuration  scan="true" scanPeriod="60 seconds" debug="false">
    <contextName>logback</contextName>
    <property name="log.path" value="/data/server/tomcat/logs/plus.log" />
    <!--输出到控制台-->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <!--格式化输出：%d:表示日期    %thread:表示线程名     %-5level:级别从左显示5个字符宽度  %msg:日志消息    %n:是换行符-->
            <pattern> %red(%d{yyyy-MM-dd HH:mm:ss.SSS}) %green([%thread]) %highlight(%-5level) %boldMagenta(%logger) - %cyan(%msg%n)</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>

    <!--输出到文件-->
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>plus.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
            <charset>utf8</charset>
        </encoder>

    </appender>

    <root level="info">
        <appender-ref ref="console" />
        <appender-ref ref="file" />
    </root>


</configuration>

这里我们新建个测试类来进行验证：

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

/**
 * @author tan.dg
 * @date 2018/4/19 15:20
 */
@RestController
@RequestMapping("/hello")
public class HelloController {

    @GetMapping
    public String hello(String name) {
        return "Hello , " + name;
    }
}

现在启动项目，访问127.0.0.1:8080/hello?name=springboot-aspect，观察控制台日志输出：

2018-04-19 15:28:30.066 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - URL : http://127.0.0.1:8080/hello [GET]
2018-04-19 15:28:30.066 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - IP : 127.0.0.1
2018-04-19 15:28:30.066 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - CACHE-CONTROL : no-cache
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - POSTMAN-TOKEN : 885710cc-293a-4bed-9ca8-5140e2d38fcb
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - USER-AGENT : PostmanRuntime/3.0.9
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - ACCEPT : */*
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - HOST : 127.0.0.1:8080
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - COOKIE : JSESSIONID=1DA1EBE115236D57E6FF786720A48B7A
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - ACCEPT-ENCODING : gzip, deflate
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - CONNECTION : keep-alive
2018-04-19 15:28:30.067 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - CLASS_METHOD : com.tandg.plus.web.HelloController.hello
2018-04-19 15:28:30.068 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - PARAM : ["name=springboot-aspect"]
2018-04-19 15:28:30.070 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - RESPONSE : "Hello , springboot-aspect"
2018-04-19 15:28:30.071 [http-nio-8080-exec-3] INFO  com.tandg.plus.aspect.HttpLogAspect - SPEND TIME : 5mszon

总结

Talk is cheap ， Show me the code .