从零开始实现放置游戏（五）：管理系统搭建之实现切面日志

作者：丶谦信 2019-11-07

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

这里我们以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">
<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>
<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>
<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文件中添加以下配置：

<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

相关阅读：
从零开始实现放置游戏（一）：准备工作
从零开始实现放置游戏（二）：整体框架搭建
从零开始实现放置游戏（三）：后台管理系统搭建
从零开始实现放置游戏（四）后台数值配置的增删查改
从零开始实现放置游戏（五）：管理系统搭建之实现切面日志

作者：丶谦信
博客地址：https://www.cnblogs.com/lyosaki88/p/idlewow_5.html

微信公众号

微博

头条号

百家号

网易号

知乎号

从零开始实现放置游戏（五）：管理系统搭建之实现切面日志

微信公众号

微博

头条号