從零開始實現放置游戲（五）——實現后台管理系統（3）實現切面日志

　　上一章，我們初步實現了后台管理系統的增刪查改功能。然而還有很多功能不完善。這一章，我們先把系統日志搭建起來，不管是生產問題排查，還是方便開發調試，日志都是必不可少的核心功能。所謂切面日志，比如說，我們想把每個方法的入參都記錄日志，那需要在每個方法里都寫一行記錄參數的語句，非常繁瑣。所以需要提取出切面“方法執行前”，“方法執行后”等等，然后在這個切面里進行編程，記錄入參的語句只需要寫一次。整體的流程大致如下圖：

　　

　　這里我們以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>

　　在這個配置文件中，我們定義了日志存放路徑"/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() {
    }
}

　　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);
    }
}

　　這里我們定義了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啟動方式啟動，就不會報錯了。

小結

　　本章實現了系統日志的搭建，為我們以后開發調試時快速定位問題打好基礎。

　　源碼下載地址：https://idlestudio.ctfile.com/fs/14960372-383747156

　　本文原文地址：https://www.cnblogs.com/lyosaki88/p/idlewow_5.html

　　項目交流群：329989095