基于springboot 的日志跟踪切面实现

基于AOP的请求日志跟踪实现

版本说明

• springboot版本:2.1.4.RELEASE

实现结果说明

• 基于springboot的日志切面
• 将controller、service、dao的入参和出参记录到一个特定的文件目录中。

解决思路

• 基于springAOP拦截controller,service，dao方法，打印日志。
• 通过配置RegexFilter将日志信息打印到单独的文件。

其他说明

• 本文和实际例子的差别在于修改了一些包名，其他保持不变，若因包名导致的错误，请自行修改。

实现效果举例

******************请求开始*******************
开始时间：[2019-08-21 22:21:57]
[2019-08-21 22:21:57].[IP:略]
[2019-08-21 22:21:57].[Controller:com.demo.base.usermng.controller.employee.EmployeeController.getEmployeeDetailInfo]
[2019-08-21 22:21:57].[Controller参数：{1}]
[2019-08-21 22:21:57].[Service:com.dolphtech.base.demo.service.employee.impl.EmployeeServiceImpl.getEmployeeDetailInfo]
[2019-08-21 22:21:57].[Service参数：{1,true}]
[2019-08-21 22:21:57].[DAO：com.sun.proxy.$Proxy167.selectOne]
[2019-08-21 22:21:57].[DAO：{com.baomidou.mybatisplus.core.conditions.query.QueryWrapper@60255b0f}]
[2019-08-21 22:21:57].[DAO：com.sun.proxy.$Proxy169.selectByEmployeeId]
[2019-08-21 22:21:57].[DAO：{1}]
[2019-08-21 22:21:57].[Controller返回值：{"data":{"account":"test","createTime":"2019-07-19T10:38:37","id":1,"orgId":10,"roles":[{"code":"oprator","createTime":"2019-08-15T14:04:14","id":3,"name":"操作人员"}],"statusName":"正常","type":0,"updateTime":"2019-08-14T19:15:08"},"message":"","status":"200"}]
结束时间：[2019-08-21 22:21:57]
******************请求结束*******************

具体实现

springboot整合log4j2

• pom引入包处理

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter</artifactId>
			<exclusions>
			    <!-- 去除springboot自带的longging包 -->
				<exclusion>
					<groupId>org.springframework.boot</groupId>
					<artifactId>spring-boot-starter-logging</artifactId>
				</exclusion>
			</exclusions>
		</dependency>

		<!-- Spring Boot log4j2依赖 -->
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-log4j2</artifactId>
		</dependency>

配置文件

log4j2-dev.xml配置

<?xml version="1.0" encoding="UTF-8"?>
<!--日志级别以及优先级排序: OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL -->
<!-- status log4j2内部日志级别 -->
<configuration status="INFO">
    <!-- 全局参数 -->
    <Properties>
        <Property name="pattern">%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p %c{1}:%L -%m%n</Property>
        <!-- 绝对文件日志目录 -->
        <Property name="basePath">D:\logs\</Property>
        <!-- 文件名称 -->
        <Property name="displayName">demo</Property>

        <!-- 配置请求的跟踪关键字，含当前关键字的日志，会被打印出来 -->
        <!-- 后期建议配置成标志位，专门标记请求日志 -->
        <Property name="requestTraceMessage">[\s\S]*请求开始[\s\S]*</Property>
    </Properties>
    <Appenders>
        <!-- 定义控制台输出日志的格式 -->
        <Console name="console" target="SYSTEM_OUT" follow="true">
            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>
        </Console>

        <!-- debug级别的日志文件 -->
        <RollingFile name="debug" fileName="${basePath}${displayName}_debug.log"
                     filePattern="${basePath}${displayName}_debug_%d{yyyy-MM-dd}_%i.log.gz">
            <Filters>
                <!-- 过滤掉请求日志 -->
                <RegexFilter regex=".*${requestTraceMessage}.*" onMatch="DENY" onMismatch="NEUTRAL"/>
                <LevelFilter level="debug" onMatch="ACCEPT" onMismatch="DENY" />
            </Filters>
            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>
            <Policies>
                <!-- 按文件大小归档 -->
                <SizeBasedTriggeringPolicy size="50 MB"/>
                <!-- 按时间模式归档，单位由filePattern的%d日期格式指定 -->
                <TimeBasedTriggeringPolicy/>
            </Policies>
        </RollingFile>

        <!-- info级别的日志文件 -->
        <RollingFile name="info" fileName="${basePath}${displayName}_info.log"
                     filePattern="${basePath}${displayName}_info_%d{yyyy-MM-dd}_%i.log.gz">
            <Filters>
                <!-- 过滤掉请求日志 -->
                <RegexFilter regex="${requestTraceMessage}" onMatch="DENY" onMismatch="NEUTRAL"/>
                <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>
            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>
            <Policies>
                <!-- 按文件大小归档 -->
                <SizeBasedTriggeringPolicy size="50 MB"/>
                <!-- 按时间模式归档，单位由filePattern的%d日期格式指定 -->
                <TimeBasedTriggeringPolicy/>
            </Policies>
        </RollingFile>

        <!-- 请求追踪日志文件 -->
        <RollingFile name="request" fileName="${basePath}${displayName}_request.log"
                     filePattern="${basePath}${displayName}_request_%d{yyyy-MM-dd}_%i.log.gz">

            <Filters>
                <!-- 只打印请求日志 -->
                <RegexFilter regex="${requestTraceMessage}" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>
            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>
            <Policies>
                <!-- 按文件大小归档 -->
                <SizeBasedTriggeringPolicy size="50 MB"/>
                <!-- 按时间模式归档，单位由filePattern的%d日期格式指定 -->
                <TimeBasedTriggeringPolicy/>
            </Policies>
        </RollingFile>

        <!-- 警告级别的日志文件 -->
        <RollingFile name="warn" fileName="${basePath}${displayName}_warn.log"
                     filePattern="${basePath}${displayName}_warn_%d{yyyy-MM-dd}_%i.log.gz">
            <Filters>
                <ThresholdFilter level="error" onMatch="DENY" onMismatch="NEUTRAL"/>
                <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY" />
            </Filters>
            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>
            <Policies>
                <!-- 按文件大小归档 -->
                <SizeBasedTriggeringPolicy size="50 MB"/>
                <!-- 按时间模式归档，单位由filePattern的%d日期格式指定 -->
                <TimeBasedTriggeringPolicy/>
            </Policies>
        </RollingFile>

        <!-- 定义error级别的日志文件 -->
        <RollingFile name="error" fileName="${basePath}${displayName}_error.log"
                     filePattern="${basePath}${displayName}_error_%d{yyyy-MM-dd}_%i.log.gz">
            <Filters>
                <!-- 匹配error级别及以上的日志，其他的拒绝 -->
                <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>

            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>

            <Policies>
                <!-- 按文件大小归档 -->
                <SizeBasedTriggeringPolicy size="50 MB"/>
                <!-- 按时间模式归档，单位由filePattern的%d日期格式指定 -->
                <TimeBasedTriggeringPolicy/>
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Logger name="org.springframework" level="WARN" />
        <Root level="info">
            <AppenderRef ref="console" />
            <AppenderRef ref="error" />
            <AppenderRef ref="info" />
            <AppenderRef ref="debug" />
            <AppenderRef ref="warn" />
            <AppenderRef ref="request" />
        </Root>
    </Loggers>
</configuration>

application.yml添加配置

logging:
  config: classpath:log4j2-dev.xml

• 通过上述两个配置，就可以正常打印日志了。
• 此处需要先测试通过，主要是要配置上面的Properties,其他配置看个人意愿修改

测试demo

• 在启动类的main方法中添加下面几行测试代码(测试代码可自行更换)

    /**
     * 应用启动入口
     * @param args
     */
    public static void main(String[] args) {
        SpringApplication springApplication = new SpringApplication(DemoApplication.class);
        springApplication.run(args);

        //打印日志
        System.out.println("1111111111111111111111111");
        LoggerUtils.info(logger, "开始请求:这是在测试日志打印");
        LoggerUtils.debug(logger, "这是debug日志");
        LoggerUtils.info(logger, "这是info日志");
        LoggerUtils.error(logger, "这是error日志");
        logger.warn("这是warn日志");
    }

添加切面

添加切面,代码如下

package com.framework.web.aop;

import com.framework.common.constant.MarkConstant;
import com.framework.common.enums.DateFormatEnum;
import com.framework.common.util.JsonUtils;
import com.framework.common.util.date.LocalDateTimeUtils;
import com.framework.core.util.LoggerUtils;
import com.framework.web.util.IpAddressUtils;
import org.apache.commons.collections.CollectionUtils;
import org.apache.commons.lang3.ArrayUtils;
import org.apache.commons.lang3.StringUtils;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;
import java.io.PrintWriter;
import java.io.Serializable;
import java.io.StringWriter;
import java.util.ArrayList;
import java.util.List;

/**
 * <T>User：</T>
 * <T>Description：web请求日志切面</T>
 * <T>Create time：2019/8/21 18:37</T>
 * <T>Company: </T>
 * <T>Update record(who,time,message):</T>
 */
@Aspect
public class ApiRequestLogAspect {

    //日志缓存列表
    private List<String> logList;

    //默认打印的响应结果的最大长度
    private static final int DEFAULT_RETURN_LEN = 2048;

    //controller类末尾字符串
    private static final String CONTROLLER_END = "Controller";


    //日志句柄
    private static Logger logger = LoggerFactory.getLogger(ApiRequestLogAspect.class);

    private final String controllerExecution = "execution(* com.demo..*..*.controller..*.*(..))";

    private final String serviceExecution = "execution(* com.demo..*..*.service..*.*(..))";

    private final String daoExecution = "execution(* com.demo..*..*.dao..*.*(..))";


    /**
     * controller切点
     */
    @Pointcut(controllerExecution)
    public void controllerCut() {

    }

    /**
     * service切点
     */
    @Pointcut(serviceExecution)
    public void serviceCut() {

    }

    /**
     * dao切点
     */
    @Pointcut(daoExecution)
    public void daoCut() {

    }

    /*
     * 执行controller方法之前
     * @param joinPoint
     */
    @Before("controllerCut()")
    public void doControllerBefore(JoinPoint joinPoint) {
        logList = new ArrayList<>();
        String currentTime = getCurrentTime();
        saveLogList(MarkConstant.ENTER);
        saveLogList("******************请求开始*******************");
        saveLogList("开始时间：" + currentTime);
        saveLogList(currentTime + MarkConstant.DOT + addBrackets("IP:" + IpAddressUtils.getIpAddr(getRequest())));
        saveLogList(currentTime + MarkConstant.DOT + addBrackets("Controller:" + getFullMethodName(joinPoint)));
        String args = ArrayUtils.toString(joinPoint.getArgs());

        //过滤掉包含密码字样的参数打出
        if(!args.contains("password")){
            saveLogList(currentTime + MarkConstant.DOT + addBrackets("Controller参数：" + args));
        }
    }

    /*
     * 执行service方法之前
     * @param joinPoint
     */
    @Before("serviceCut()")
    public void doServiceBefore(JoinPoint joinPoint) {
        String currentTime = getCurrentTime();
        saveLogList(currentTime + MarkConstant.DOT + addBrackets("Service:" + getFullMethodName(joinPoint)));
        String args = ArrayUtils.toString(joinPoint.getArgs());
        saveLogList(currentTime + MarkConstant.DOT + addBrackets("Service参数：" + args));
    }

    /*
     * 执行dao方法之前
     * @param joinPoint
     */
    @Before("daoCut()")
    public void doDAOBefore(JoinPoint joinPoint) {
        String currentTime = getCurrentTime();
        saveLogList(currentTime + MarkConstant.DOT + addBrackets("DAO：" + getFullMethodName(joinPoint)));
        String args = ArrayUtils.toString(joinPoint.getArgs());
        saveLogList(currentTime + MarkConstant.DOT + addBrackets("DAO：" + args));
    }

    /*
     * 定义方法正常返回的后置处理
     * @param rvt
     */
    @AfterReturning(returning = "rvt", pointcut = "controllerCut()")
    public void afterReturn(JoinPoint joinPoint, Object rvt) {
        //controller方法执行方法返回事件  其他暂时不执行
        String className = getSimpleClassName(joinPoint);
        String currentTime = getCurrentTime();
        saveLogList(currentTime + MarkConstant.DOT + addBrackets("Controller返回值：" + returnToString(rvt)));
        saveLogList("结束时间：" + currentTime);
        saveLogList("******************请求结束*******************");
        printLog(false);
    }

    /*
     * 结果转字符串
     * @param rvt
     * @return
     */
    private String returnToString(Object rvt) {
        String jsonResult;
        if (rvt instanceof List) {
            jsonResult = JsonUtils.toArrayJson((List)rvt);
        } else if (rvt instanceof Serializable) {
            //fastJson提供的toJSONString方法，有个重载方法，可以传入过滤器，用以对key、值的过滤。
            //后期若需要在打印日志的时候，过滤敏感词，可以在这边处理
            jsonResult = JsonUtils.toJson(rvt);
        } else {
            jsonResult = rvt + "";
        }
        if (StringUtils.isNotBlank(jsonResult) && jsonResult.length() > DEFAULT_RETURN_LEN) {
            jsonResult = jsonResult.substring(0, DEFAULT_RETURN_LEN);
        }
        return jsonResult;
    }

    /*
     * 当方法抛出异常时，提供异常处理
     * @param tw
     */
    @AfterThrowing(throwing = "tw", pointcut = "controllerCut()")
    public void afterThrow(JoinPoint joinPoint, Throwable tw) {
        //controller方法执行方法返回事件  其他暂时不执行
        String className = getSimpleClassName(joinPoint);
        saveLogList("结束时间：" + getCurrentTime());
        saveLogList("=========访问结束================");
        saveLogList(getStackTrace(tw));
        printLog(true);
    }

    /*
     * 保存日志信息
     * @param log 要保存的日志信息
     */
    private void saveLogList(String log){
        if(null != logList){
            logList.add(log);
        }
    }

    /*
     * 打印日志
     */
    private void printLog(boolean isError){
        try{
            if(!CollectionUtils.isEmpty(logList)){
                StringBuilder info = new StringBuilder();
                logList.forEach(logStr -> info.append(logStr).append("\n"));
                if(isError){
                    LoggerUtils.error(logger, info.toString());
                }else{
                    LoggerUtils.info(logger, info.toString());
                }
            }
            logList = null;
        }catch (Exception e){
            e.printStackTrace();
        }
    }

    /*
     * 获取请求
     * @return
     */
    private HttpServletRequest getRequest() {
        return ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();
    }

    /*
     * 获取当前时间
     * @return
     */
    private String getCurrentTime() {
        String currentTime = LocalDateTimeUtils.getCurrentDate(DateFormatEnum.DATE_FORMAT_18);
        return addBrackets(currentTime);
    }

    /*
     * 添加中括号
     * @param value
     * @return
     */
    private String addBrackets(String value) {
        return MarkConstant.LEFT_BRACKET + value + MarkConstant.RIGHT_BRACKET;
    }


    /*
     * 获取完整的方法名
     * @param joinPoint
     * @return
     */
    private String getFullMethodName(JoinPoint joinPoint){
        return joinPoint.getTarget().getClass().getName() + MarkConstant.DOT + joinPoint.getSignature().getName();
    }

    /*
     * 获取类名
     * @param joinPoint
     * @return
     */
    private String getSimpleClassName(JoinPoint joinPoint) {
        return joinPoint.getTarget().getClass().getSimpleName();
    }

    /*
     * 获取异常的堆栈信息
     * @param t
     * @return
     */
    private static String getStackTrace(Throwable t) {
        StringWriter sw = new StringWriter();
        PrintWriter pw = new PrintWriter(sw);
        try {
            t.printStackTrace(pw);
            return sw.toString();
        } finally{
            pw.close();
        }
    }
}

附加工具类主代码

• DateFormatEnum

package com.framework.common.enums;

/**
 * <T>User：</T>
 * <T>Description：日期格式枚举类</T>
 * <T>Create time：2019/8/9 16:54</T>
 * <T>Update record(who,time,message):</T>
 */
public enum DateFormatEnum {
    /**
     * yyyyMMddHHmmss
     */
    DATE_FORMAT_14("yyyyMMddHHmmss"),

    /**
     * yyyyMMdd
     */
    DATE_FORMAT_8("yyyyMMdd"),

    /**
     * yyMMdd
     */
    DATE_FORMAT_6("yyMMdd"),

    /**
     * yyyy-MM-dd
     */
    DATE_FORMAT_10("yyyy-MM-dd"),

    /**
     * yyyy-MM-dd HH:mm:ss
     */
    DATE_FORMAT_18("yyyy-MM-dd HH:mm:ss"),

    /**
     * yyyy-MM-dd HH:mm:ss,SSS
     */
    DATE_FORMAT_22("yyyy-MM-dd HH:mm:ss,SSS");

    private String pattern;

    DateFormatEnum(String pattern) {
        this.pattern = pattern;
    }

    /**
     * 获取 pattern 的值
     *
     * @return pattern
     */
    public String getPattern() {
        return pattern;
    }

    /**
     * 设置 pattern 的值
     *
     * @param pattern
     */
    public void setPattern(String pattern) {
        this.pattern = pattern;
    }
}

• LocalDateTimeUtils

/**
 * <T>User：</T>
 * <T>Description：LocalDateTime工具类</T>
 * <T>Create time：2019/5/29 16:20</T>
 * <T>Company: </T>
 * <T>Update record(who,time,message):</T>
 */
public class LocalDateTimeUtils {
    /**
     * localDateTime日期格式化成字符串
     * @param localDateTime localDateTime日期
     * @param dateFormat 日期格式
     * @return 格式化后的日期
     */
    public static String formatDate(LocalDateTime localDateTime, DateFormatEnum dateFormat) {
        return localDateTime.format(DateTimeFormatter.ofPattern(dateFormat.getPattern()));
    }

    /**
     * 获取当前时间
     * @param pattern 时间格式
     * @return
     */
    public static String getCurrentDate(DateFormatEnum pattern) {
        return formatDate(LocalDateTime.now(), pattern);
    }
}

• 特别说明：以下几个类，只是一些常用的工具类，可自己实现,需要请留言

import com.framework.common.constant.MarkConstant;
import com.framework.common.enums.DateFormatEnum;
import com.framework.common.util.JsonUtils;
import com.framework.common.util.date.LocalDateTimeUtils;
import com.framework.core.util.LoggerUtils;
import com.framework.web.util.IpAddressUtils;

切面注入到springIOC

@Configuration
public class AspectAutoConfiguration {
    @Bean
    public ApiRequestLogAspect apiRequestLogAspect() {
        return new ApiRequestLogAspect();
    }
}

• 此处也可以用@Component注解注入到springIOC,需要注意包的扫描位置

修改shiro Realm中的注入类的方式

• 按上面配置，发现controller切点执行成功,service切点执行失败,经查，是因为项目中整合了shiro导致的，需要在Realm中加@Lazy就能解决(原因不详)

public class BaseUserRealm extends AuthorizingRealm {
    @Autowired
    @Lazy
    private IEmployeeService employeeService;
    ....

启动项目

• 启动项目，通过postman或者其他方式，调用接口，此时请求日志会单独打印到demo_request.log中

难点总结

• log4j2和logback配置文件的配置方式不同，网上log4j2的配置资源较杂。
• 不同的配置文件，采用的过滤器不同。本文通过RegexFilter拦截特殊字符，将日志打印到特定文件中
• shiro导致service无法拦截，是最大的坑。原因未查。