从零开始实现放置游戏（五）——实现挂机战斗（3）引入日志功能并实现切面日志

470 0 0

作者:安静小角落

　　上一章，我们初步实现了后台管理系统的增删查改功能。然而还有很多功能不完善。这一章，我们先把系统日志搭建起来，不管是生产问题排查，还是方便开发调试，日志都是必不可少的核心功能。所谓切面日志，比如说，我们想把每个方法的入参都记录日志，那需要在每个方法里都写一行记录参数的语句，非常繁琐。所以需要提取出切面“方法执行前”，“方法执行后”等等，然后在这个切面里进行编程，记录入参的语句只需要写一次。整体的流程大致如下图：

　　这里我们以rms模块为例，其他模块需要记录日志的地方参照本模块即可。

一、引入依赖

　　java里，日志的实现一般是common-logging+log4j2或slf4j+logback，其中common-logging和slf4j是接口定义，log4j2和logback是具体实现。这里我们使用log4j，common-logging在其他包中已经间接引用了，无需重复添加，在pom中添加log4j的依赖即可（这里版本是2.11.2，也称log4j2，和1.x版本的区别较大，配置不通用，在网上学习时需注意）：

<!-- 日志相关 -->
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.11.2</version>
</dependency>

二、添加配置文件

　　在"/resources/"资源文件目录下新建"log4j2.xml"，这是log4j的默认配置路径和文件名。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="OFF" monitorInterval="1800">
    <properties>
        <property name="LOG_HOME">/logs/idlewow-rms/</property>
    </properties>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </Console>
        <RollingFile name="info" fileName="${LOG_HOME}/info.log"
                     filePattern="${LOG_HOME}/info-%d{yyyyMMdd}-%i.log"
                     immediateFlush="true">
            <!-- 只输出level及以上级别的信息（onMatch），其他的直接拒绝（onMismatch） -->
            <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{HH:mm:ss.SSS} %level [%thread][%X{sessionId}][%file:%line] - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true" />
                <SizeBasedTriggeringPolicy size="20 MB"/>
            </Policies>
        </RollingFile>
        <RollingFile name="warn" fileName="${LOG_HOME}/warn.log"
                     filePattern="${LOG_HOME}/warn-%d{yyyyMMdd}-%i.log"
                     immediateFlush="true">
            <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{HH:mm:ss.SSS} %level [%thread][%X{sessionId}][%file:%line] - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"  />
                <SizeBasedTriggeringPolicy size="20 MB"/>
            </Policies>
            <!-- 同一文件夹下最多保存20个日志文件，默认为7 -->
            <DefaultRolloverStrategy max="20"/>
        </RollingFile>
        <RollingFile name="error" fileName="${LOG_HOME}/error.log"
                     filePattern="${LOG_HOME}/error-%d{yyyyMMdd}-%i.log"
                     immediateFlush="true">
            <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{HH:mm:ss.SSS} %level [%thread][%X{sessionId}][%file:%line] - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"  />
                <SizeBasedTriggeringPolicy size="20 MB"/>
            </Policies>
            <DefaultRolloverStrategy max="20"/>
        </RollingFile>
    </Appenders>
    <Loggers>
        <!--过滤掉spring和mybatis的一些无用的DEBUG信息-->
        <logger name="org.springframework" level="INFO"></logger>
        <logger name="org.mybatis" level="INFO"></logger>
        <Root level="all">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="info"/>
            <AppenderRef ref="warn"/>
            <AppenderRef ref="error"/>
        </Root>
    </Loggers>
</Configuration>

log4j2.xml

　　在这个配置文件中，我们定义了日志存放路径"/logs/idlewow-rms/"，windows下默认D盘。控制台的日志输出格式，以及3个级别INFO, WARN, ERROR的文件输出方式。同时把spring组件的日志级别提高到info，过滤掉debug信息。

　　以info级别的日志为例，我们定义了日志的输出格式"[时间] [日志级别] [线程名称][SessionId][文件名称 - 代码行数] - 日志信息。日志的滚动策略，按天滚动，每1天生成1个日志文件，或大于20MB时，生成一个日志文件。

三、日志打印SessionId

　　上面的配置中，我们定义了日志需要打印Sessionid，主要是方便精准定位问题。但log4j默认不支持此功能，需要我们单独实现一个Filter，在请求进来时，获取sessionId，并存到log4j的上下文中。

package com.idlewow.rms.filter;

import org.apache.logging.log4j.ThreadContext;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpSession;
import java.io.IOException;

public class LogSessionFilter implements Filter {
    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
    }

    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        try {
            HttpSession session = ((HttpServletRequest) request).getSession(false);
            if (session != null) {
                ThreadContext.put("sessionId", session.getId());
            }

            chain.doFilter(request, response);
        } finally {
            ThreadContext.remove("sessionId");
        }
    }

    @Override
    public void destroy() {
    }
}

LogSessionFilter.java

　　Filter是servlet相关的机制，因此需要在web.xml文件中添加以下配置：

<!-- log4j记录session -->
<filter>
    <filter-name>logSessionFilter</filter-name>
    <filter-class>com.idlewow.rms.filter.LogSessionFilter</filter-class>
</filter>
<filter-mapping>
    <filter-name>logSessionFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

四、具体使用

　　配置全部完成，在我们想要使用log4j打印日志时，需要先获取一个logger，一般我们在contoller里声明一个final的成员变量，如下：

    private final Logger logger = LogManager.getLogger(this.getClass().getName());

　　然后，在各个方法中，想记录日志时，只需像下面这样，即可打印对应级别的日志，

logger.info("hello world");
logger.warn("hello world");
logger.error("hello world");

　　通常，在打印异常时，还会打印堆栈信息，方便定位问题，如下（在第一个参数传入异常信息，第二个参数传入异常对象）：

logger.error(ex.getMessage(), ex);

五、切面日志的实现

　　上面的日志功能，已经能让我们在程序中随时记录日志，下面我们实现切面日志的功能。这里需要依赖的两个包，spring-aop和aspectjweaver，前面我们已经引用过了。

　　然后，我们需要一个类，定义切点、切面方法。新建一个包com.idlewow.rms.config，在此包下新建类LogAspect，代码如下：

package com.idlewow.rms.config;

import com.alibaba.fastjson.JSON;
import com.idlewow.admin.model.SysAdmin;
import com.idlewow.rms.controller.BaseController;
import com.idlewow.rms.vo.RequestLog;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
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 javax.servlet.http.HttpSession;
import java.util.Date;
import java.util.Random;

@Aspect
@Component
public class LogAspect {

    private final static Logger logger = LogManager.getLogger(LogAspect.class);

    // ..表示包及子包 该方法代表controller层的所有方法
    @Pointcut("execution(public * com.idlewow.rms.controller..*.*(..))")
    public void commonPoint() {
    }

    @Pointcut("@annotation(com.idlewow.rms.support.annotation.LogResult)")
    public void returnPoint() {
    }


    @Before("commonPoint()")
    public void before(JoinPoint joinPoint) throws Exception {
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
        HttpSession session = request.getSession(false);
        String username = "anyone";
        if (session != null && session.getAttribute(BaseController.LoginUserKey) != null) {
            username = ((SysAdmin) session.getAttribute(BaseController.LoginUserKey)).getUsername();
        }

        String trackId = username + "_" + System.currentTimeMillis() + "_" + new Random().nextInt(100);
        request.setAttribute("ct_begin", new Date().getTime());
        request.setAttribute("ct_id", trackId);
        RequestLog requestLog = new RequestLog();
        requestLog.setUrl(request.getRequestURI());
        requestLog.setType(request.getMethod());
        requestLog.setIp(request.getRemoteAddr());
        requestLog.setMethod(joinPoint.getSignature().toShortString());
        requestLog.setArgs(joinPoint.getArgs());
        logger.info("[" + trackId + "]请求开始：" + requestLog.toString());
    }

    @After("commonPoint()")
    public void after(JoinPoint joinPoint) {
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
        String trackId = request.getAttribute("ct_id").toString();
        long totalTime = new Date().getTime() - (long) request.getAttribute("ct_begin");
        logger.info("[" + trackId + "]请求耗时：" + totalTime + "ms");
    }

    @AfterReturning(returning = "result", pointcut = "commonPoint()")
    public void afterReturn(JoinPoint joinPoint, Object result) throws Exception {
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
        String trackId = request.getAttribute("ct_id").toString();
        logger.info("[" + trackId + "]请求结果：" + JSON.toJSONString(result));
    }

    @AfterThrowing(value = "commonPoint()", throwing = "t")
    public void afterThrow(JoinPoint joinPoint, Throwable t) {
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
        String trackId = request.getAttribute("ct_id").toString();
        logger.error("[" + trackId + "]系统异常：" + t.getMessage(), t);
    }
}

LogAspect.java

　　这里我们定义了2个切点，commonPoint表示controller包下的所有public方法，returnPoint表示所有打了LogResult注解的方法（这是我们自定义的一个注解）。

　　然后实现了4个切面方法，目前对应的都是commonPoint切点。

　　其中，before在每次方法执行前都会执行，我们在这个方法里打印info级别的日志，记录请求URL、IP、入参等信息，同时记录请求起始时间，并分配一个trackId用来定位问题（假如同一个用户瞬间执行某个请求N次，SessionId都是相同的，我们就无法确定这N次中，每个返回数据对应的到底是哪次请求）；

　　　　　after在每次方法之后后都会执行，我们在这个方法里记录每次请求耗时；

　　　　　afterThrowing在抛出异常时才会执行，我们在这个方法里打印error级别的日志;

　　　　　afterReturn是在方法正常返回时执行，我们在这个方法里打印返回结果。这里这个方法我们对应的是commonPoint切点，即所有方法都会打印返回结果，在实际应用时，可视情况改为对应returnPoint切点，这样只有加了@LogReuslt注解的方法，才会打印返回结果。

　　最后，需要在spring的配置文件中，添加一行配置：

<aop:aspectj-autoproxy proxy-target-class="true"></aop:aspectj-autoproxy>

　　注意：这句话应该配置在spring-mvc.xml中扫描完controller包之后。因为我们这里拦截的是controller的方法，在applicationContext中，我们还没有扫描controller类。这里老手对java web, spring框架中各部分的执行顺序了解，更容易理解。新手照着配即可，做多了自然就懂了。

六、运行效果

　　至此，日志功能已经实现，我们运行一下看下效果：

　　注意：添加log4j2依赖后，通过maven插件启动时，会有红字提示：严重: Unable to process Jar entry [META-INF/versions/9/module-info.class] from Jar [jar:file:/D:/apache-maven-3.6.1/package/org/apache/logging/log4j/log4j-api/2.11.2/log4j-api-2.11.2.jar!/] for annotations。这是因为maven插件内置的tomcat7.0.47版本过低，但不影响程序正常运行。

maven插件不能修改tomcat版本，而且13年后就停止更新了（这里不知是否是有别的新东西取代所以停更了）。目前，如果因为tomcat版本低等问题导致有错误提示，可以直接下载一个新版本的tomcat，比如前言章节中的7.0.85，使用IDE集成的tomcat启动方式启动，就不会报错了。