從零開始實現放置遊戲（五）——實現掛機戰鬥（3）引入日誌功能並實現切面日誌

丶謙信發表於2019-06-20

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

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