最近在给老系统添加日志管理模块，主要记录用户的操作日志。操作日志不同于系统日志，它要求内容简洁且易读，同时日志管理要求做到三点：（1）不侵入业务逻辑；（2）可作为组件独立使用；（3）支持权限管理和可视化查询。因此本篇将从上述三个要求出发，学习和实践如何记录操作日志。
操作日志使用场景 操作日志与系统日志区别 当对某个对象进行新增、修改和查询操作后，通常需要记录对象的新旧状态，这其实就是操作日志，一般而已操作日志都是给用户查阅的，因此可读性要求较高。最常见的就是物流信息的更新，这其实是针对该快递对象的更新记录，里面会告诉用户包裹转到何时何地。
而系统日志通常是作为开发人员排查和解决问题的依据，一般记录在指定的日志文件中，由于是给开发人员使用的，所以可读性要求不高，里面只记录一些重点信息，如代码当前输出的信息。
操作日志分类 一般来说，操作日志分类分为三类，下面依次进行简要学习：
当然实际可能修改的字段不止以上几种，可能涉及到的内容较多，但基本上和上述三类差异不大。
实现方案 使用Canal监听数据库 Canal是一款基于MySQL数据库增量日志解析，提供增量数据订阅和消费的开源组件，通过采用监听数据库Binglog的方式来知道具体是哪些数据发生了修改，然后根据修改的数据来记录用户操作日志。
这种方式完全不侵入原来的业务代码，但是缺点也很明显，就是只能针对数据库的更改做记录，如果涉及到其他团队的RPC调用，这无法监听数据库因此只能手动记录操作日志。举个简单的例子，用户下单后调用短信通知服务，告诉用户下单成功，毫无疑问短信通知服务肯定是公共服务，只能下单方法调用了这个RPC，那么只能在下单方法中记录给用户发送通知的操作记录。关于一部分的内容，可以参考后续文章。
通过日志文件记录 通过日志文件方式，这是最常用的方式，直接在调用的时候输出一些调用信息：
1 2 3 log.info("用户登录"); log.info("用户：{}，创建订单，订单号为{}",userId,orderId); log.info("用户：{}，修改了订单备注信息，由“{}”修改为“{}”",userId,oldInfo,newInfo);
可以看到这里存在三个问题：（1）如何获取到用户信息；（2）操作日志如何与系统日志分开；（3）如何生成可读性高的日志信息。
如何获取到用户信息 如何获取用户信息，这里有很多种方式，可以通过拦截器或者AOP方式，传入请求然后从请求中获取，并将用户信息存入MDC（Mapped Diagnostic Context，映射调试上下文）中，那么相应的伪代码如下所示：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 @Component public class UserInterceptor extends HandlerInterceptor { @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { //获取到用户ID String userId = getUserInfo(request); //把用户ID放入MDC上下文中 MDC.put("userId", userId ); return super.preHandle(request, response, handler); } private String getUserInfo(HttpServletRequest request) { // 通过SSO、Cookie或者Auth信息获取当前登陆的用户信息 return null; } }
接着将用户ID格式化到日志文件中，可使用%X{userId}变量来获取MDC中的用户ID：
1 <pattern>"%d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %X{userId} %logger{30}.%method:%L - %msg%n"</pattern>
操作日志如何与系统日志分开 针对这种情况，通俗做法就是通过Log的配置文件来将操作日志放到单独的日志文件中：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 <appender name="businessLogAppender" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>logs/business.log</File> <append>true</append> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>INFO</level> <onMatch>ACCEPT</onMatch> <onMismatch>DENY</onMismatch> </filter> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>logs/业务A.%d.%i.log</fileNamePattern> <maxHistory>90</maxHistory> <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <maxFileSize>10MB</maxFileSize> </timeBasedFileNamingAndTriggeringPolicy> </rollingPolicy> <encoder> <pattern>"%d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %X{userId} %logger{30}.%method:%L - %msg%n"</pattern> <charset>UTF-8</charset> </encoder> </appender> <logger name="userlogInLog" additivity="false" level="INFO"> <appender-ref ref="userlogInLogAppender"/> </logger>
之后只需在使用的时候记录一下这个日志即可：
1 2 3 4 5 //记录特定的日志类 private final Logger userlogInLog= LoggerFactory.getLogger("userlogInLog"); //日志存储 userlogInLog.info("用户登录");
如何生成可读性高的日志信息 这种一般可以使用AOP或者LogUtil方式，之后将生成的日志单独保存在一个文件中，后续通过ELK系统将其收集、过滤、存储和展示。
通过LogUtil方式记录 可以在业务逻辑代码中调用封装好的日志记录工具类来随时记录用户操作：
1 2 3 4 LogUtil.log("用户登录，登录人：%s",userId) LogUtil.log("用户：%s，创建订单，订单号为%d",userId,orderId); String template = "用户：%s，修改了订单号%d的备注信息，由“%s”修改为“%s”"; LogUtil.log(String.format(tempalte, "张三", "10001, "微辣","中辣"));
这只是记录用户的简单操作，在实际开发过程中可能比这要复杂的多，可能针对不同的业务逻辑，记录的格式和值完全不同，更重要的是将日志这种与实际业务逻辑不相关的内容深度融合在了业务代码中。
通过AOP方式记录 为了让日志与业务逻辑解耦，更多的是使用AOP配合注解方式来记录用户操作：
1 2 3 4 5 @OperationRecordLog(content="用户修改了订单信息") public void updateOrder(HttpRequest request){ // 用户修改订单逻辑 updateOrder(request); }
这种方式可以做到完全不侵入业务代码，但是记录的日志格式不符合预期，格式是固定的，其实这个可以使用动态模板来实现。
动态模板 动态模板其实就是通过解析变量占位符来解析模板，进而实现通过注解记录操作日志这一目的。模板解析的方式有很多种，这里使用SpEL（Spring Expression Language）来实现，我们希望的日志记录结构如下：
1 2 3 4 5 @OperationRecordLog(content="用户修改了订单信息，将备注由"#oldRemark"，修改为"#newRemark"") public void updateOrder(HttpRequest request,String newRemark){ // 用户修改订单逻辑 updateOrder(request,newRemark); }
别看上面的日志输出格式只提到了oldRemark和newRemark这两个参数，其实隐含了两个更重要的信息，即操作人和订单id，那么这两个参数如何获取呢？同时这个方法传入的是修改值，而旧值如果用户不传入，此时还需要在业务中查询，而这个仅仅是因为操作日志记录需要，实际业务却不需要，所以使得方式不够优雅。
为了解决操作人和订单id的显示问题，我们需要将操作日志修改为如下所示格式：
1 2 3 4 5 6 7 8 @OperationRecordLog( content="用户修改了订单信息，将备注由"#oldRemark"，修改为"#newRemark"", operator="#request.userId",bisId="#request.orderId" ) public void updateOrder(HttpRequest request,String newRemark){ // 用户修改订单逻辑 updateOrder(request,newRemark); }
这里我们在日志记录格式中添加了操作人和订单号，其实这种获取操作人的方式可能不太正确，一般在Web项目中，用户信息都是保存在一个线程上下文的静态方法中，所以操作人的信息一般是通过如下方式，假设获取当前登录用户信息的方法为UserContext.getCurrentUserInfo()：
1 operator="#{T(com.bamboo.user.UserContext).getCurrentUserInfo()}"
但是这样获取用户信息的方式也太长了，而且并不是所有的地方都需要获取登录用户的信息，因此可以将这个operator参数的值设置为可选项，这样用户可以填写操作人，如果没填那么就可以从UserContext山下文中获取当前登录用户的信息。此时操作日志的格式就变成如下所示：
1 2 3 4 5 6 7 8 @OperationRecordLog( content="用户修改了订单信息，将备注由"#oldRemark"，修改为"#newRemark"", bisId="#request.orderId" ) public void updateOrder(HttpRequest request,String newRemark){ // 用户修改订单逻辑 updateOrder(request,newRemark); }
现在还有一个问题，就是需要添加一个旧的值oldRemark，这个值的获取非常尴尬，因为用户不传入这个参数，因此我们必须自行将这个oldRemark查询出来，然后将其放到操作日志的线程上下文中，这样后续模板在解析的时候就可以使用了。那么此时操作日志的格式就变成如下所示：
1 2 3 4 5 6 7 8 9 10 11 12 @OperationRecordLog( content="用户修改了订单信息，将备注由"#oldRemark"，修改为"#newRemark"", bisId="#request.orderId" ) public void updateOrder(HttpRequest request,String newRemark){ //查询出原来的备注信息 Stirng oldRemark = orderService.query(reuest); //将原来的备注信息添加到日志记录线程上下文中 LogRecordContext.put("oldRemark",oldRemark); // 用户修改订单逻辑 updateOrder(request,newRemark); }
可以看到这里我们使用LogRecordContext这个日志记录线程上下文来记录方法参数之外的变量，更重要的是它不破坏原有方法传递的参数信息。不过这种方式还是有问题的，因为它在业务代码中插入了一些实际业务逻辑不需要的代码，这一点其实可通过自定义函数来解决，后面会介绍。
经过上面的修改，此时操作日志的格式就变成如下所示：
1 用户修改了订单信息，将备注由"#oldRemark"，修改为"#newRemark"。
如果这个oldRemark和newRemark是人可读的字符串，这肯定没问题，但是如果是某种业务代码，如口味代码，那么就可能变成：
1 用户修改了订单信息，将备注由"101"，修改为"102"。
用户不知道这个101和102具体是指什么，用户关心的是可读的信息，所以此时还需要通过LogRecordContext来查询并进行替换展示。
前面说过如果开发者不想将业务逻辑和日志记录糅杂在一起，可以使用自定义函数来进行实现。可以自定义函数将oldRemark和newRemark转换成人可读的数据，那么此时操作日志的格式就变成如下所示：
1 2 3 4 5 6 7 8 9 10 @OperationRecordLog( content="用户修改了订单信息，将备注由"{OrderInfo{#oldRemarkInfo}}"，修改为"{OrderInfo{#request.newRemark}}", bisId="#request.orderId" ) public void updateOrder(HttpRequest request){ //将原来的备注信息添加到日志记录线程上下文中 LogRecordContext.put("oldRemarkInfo",orderService.query(reuest)); // 用户修改订单逻辑 updateOrder(request,newRemark); }
这里的OrderInfo是自定义函数，我们使用大括号将Spring的SpEL表达式包裹起来，这样不仅可以将SpEL表达式和自定义函数区分开，便于解析；还可以在模板中不需要SpEL表达式的时候容易识别出来，减少不必要的SpEL解析，以提升性能。
看到这里，开发者完全可以将LogRecordContext线程上下文去掉，直接将oldRemark信息也通过自定义新的函数来获取：
1 2 3 4 5 6 7 8 @OperationRecordLog( content="用户修改了订单信息，将备注由"{OrderOldInfo{#request.orderId}}"，修改为"{OrderNewInfo{#request.newRemark}}", bisId="#request.orderId" ) public void updateOrder(HttpRequest request){ // 用户修改订单逻辑 updateOrder(request,newRemark); }
经过上面这些操作，开发者就能通过自定义新函数传入订单id就能获取到之前的订单信息，当然这要求该方法的执行必须在updateOrder方法之前，这样就可以获取到对应信息，如此一来所有的目标都实现了，同时代码几乎没有任何的侵入性。
代码实现 自定义注解 新建项目并添加web和aop依赖，接着自定义一个注解，后续所有添加该注解的方法都会被拦截并记录对应的操作记录：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 @Retention(value = RetentionPolicy.RUNTIME ) @Target(value = {ElementType.METHOD}) @Inherited @Documented public @interface OperationRecord { /** * 操作类型 */ OperationEnum type(); /** * 操作内容 */ String operation(); /** * 备注 */ String remark() default ""; }
由于备注这个信息不是所有场景下都具有的，因此这里就给了一个默认值。同时这里的操作类型定义了一个枚举类型，所以接下来就定义这个枚举类：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 /** * 操作类型 */ @AllArgsConstructor @NoArgsConstructor public enum OperationEnum { /** * 首页 */ INDEX(0), /** * 用户 */ USER(1), /** * 红包 */ REDPACKET(2), /** * 版本 */ APPVERSION(3), /** * 登录 */ LOGIN(4) ; private Integer typeId; public Integer getTypeId() { return typeId; } public void setTypeId(Integer typeId) { this.typeId = typeId; } }
自定义日志记录类 由于用户的操作日志记录需要保存到数据库中，因此接下来定义数据表和对应的实体类：
1 2 3 4 5 6 7 8 9 10 CREATE TABLE `tb_operation_record` ( `id` int(11) NOT NULL AUTO_INCREMENT, `job_number` varchar(255) NOT NULL COMMENT '工号', `login_ip` varchar(255) NOT NULL COMMENT '登录IP', `type` int(11) NOT NULL COMMENT '操作类型', `operation` varchar(1000) DEFAULT NULL COMMENT '操作内容', `operate_time` datetime DEFAULT NULL COMMENT '操作时间', `remark` varchar(1000) DEFAULT NULL COMMENT '备注', PRIMARY KEY (`id`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
实体类信息：
1 2 3 4 5 6 7 8 9 10 11 12 @AllArgsConstructor @NoArgsConstructor @Data public class TbOperationRecord { private Integer id; private String jobNumber; private String loginIp; private Integer type; private String operation; private Date operateTime; private String remark; }
自定义日志Dao层 这里我们直接通过mybatis-generate工具来生成对应的Dao代码。
自定义切面类 接下来我们需要自定义切面类AdminOperationRecordAop，然后通过AOP来拦截请求：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 @Component @Slf4j @Aspect public class AdminOperationRecordAop { private final SpelExpressionParser parser = new SpelExpressionParser(); private final DefaultParameterNameDiscoverer parameterNameDiscoverer = new DefaultParameterNameDiscoverer(); @Autowired private TbOperationRecordDao tbOperationRecordDao; public static final String TYPE = "type"; public static final String OPERATION = "operation"; public static final String REMARK = "remark"; @Pointcut("@annotation(com.poly.myinterface.OperationRecord)") public void myPointCut(){} @After("myPointCut()") public void operationRecord(JoinPoint joinPoint){ ServletRequestAttributes servletRequestAttributes = (ServletRequestAttributes)RequestContextHolder.getRequestAttributes(); HttpServletRequest request = servletRequestAttributes.getRequest(); long start = System.currentTimeMillis(); //IP地址 String userIp = IpUtils.getIpAddr(request); //工号 Object jobNumber = request.getSession().getAttribute("adminId"); try { Map<String, String> operationRecordInfo = getOperationRecordInfo(joinPoint); int type = Integer.parseInt(operationRecordInfo.get(TYPE)); String remark = operationRecordInfo.get(REMARK); String operation = operationRecordInfo.get(OPERATION); fillOperationRecord(type,remark,operation,userIp,jobNumber.toString()); log.info("【日志操作花费时间={}秒】",(System.currentTimeMillis()-start)/1000); } catch (Exception e) { log.error(e.getMessage(),e); } } private String getSPELValue(String speLString,JoinPoint joinPoint){ String str = null; if(StringUtils.isBlank(speLString)){ return ""; } try{ //方法中的参数解析过后的Spring表达式对象 Expression expression = parser.parseExpression(speLString); //Spring表达式的上下文对象(有哪些占位符，以及每种占位符的值) EvaluationContext context = new StandardEvaluationContext(); //获取被注解的方法 MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature(); //获取被注解的方法的形参 Object[] args = joinPoint.getArgs(); //获取运行时参数的名称 String[] parameterNames = parameterNameDiscoverer.getParameterNames(methodSignature.getMethod()); for(int i=0;i<parameterNames.length;i++){ context.setVariable(parameterNames[i],args[i]); } str = String.valueOf(expression.getValue(context)); log.info("【str={}】",str); }catch (Exception e){ e.printStackTrace(); } return str; } private Map<String,String> getOperationRecordInfo(JoinPoint joinPoint) throws ClassNotFoundException { Map<String, String> map = new HashMap<>(); MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature(); Method method = methodSignature.getMethod(); OperationRecord annotation = method.getAnnotation(OperationRecord.class); map.put(TYPE,annotation.type().getTypeId().toString()); map.put(REMARK,annotation.remark()); String operation = annotation.operation(); if(!operation.contains(";")){ map.put(OPERATION,operation); }else{ String[] strings = operation.split(";"); StringBuilder stringBuilder = new StringBuilder(); for(int i=0;i<strings.length;i++){ String[] split = strings[i].split("#"); String spel ="#"+split[1]; String spelValue = getSPELValue(spel, joinPoint); if(i!=strings.length-1){ stringBuilder.append(split[0]).append(spelValue).append(","); }else{ stringBuilder.append(split[0]).append(spelValue); } } map.put(OPERATION,stringBuilder.toString()); } return map; } public void fillOperationRecord(Integer type,String remark,String operation,String loginIp,String jobNumber){ TbOperationRecord tbOperationRecord = new TbOperationRecord(); tbOperationRecord.setType(type); tbOperationRecord.setRemark(remark); tbOperationRecord.setOperation(operation); tbOperationRecord.setLoginIp(loginIp); tbOperationRecord.setJobNumber(jobNumber); tbOperationRecord.setOperateTime(new Date()); tbOperationRecordDao.insert(tbOperationRecord); } }
myPointCut()是一个切点，里面设置的是之前定义的OperationRecord注解。接着我们定义了一个operationRecord方法，添加后置通知，表示在被拦截的方法执行之后这个operationRecord方法才会执行。我们通过下面的代码获取到用户请求：
1 2 ServletRequestAttributes servletRequestAttributes = (ServletRequestAttributes)RequestContextHolder.getRequestAttributes(); HttpServletRequest request = servletRequestAttributes.getRequest();
之后就通过IpUtils.getIpAddr(request)方法来获取请求来源的IP地址：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 public static String getIpAddr(HttpServletRequest request) { String ip = request.getHeader("x-forwarded-for"); if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) { ip = request.getHeader("Proxy-Client-IP"); } if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) { ip = request.getHeader("WL-Proxy-Client-IP"); } if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) { ip = request.getHeader("HTTP_CLIENT_IP"); } if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) { ip = request.getHeader("HTTP_X_FORWARDED_FOR"); } if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) { ip = request.getRemoteAddr(); } return ip; }
接着从请求携带的session中获取用户工号，之后就是获取被拦截的方法信息，从JoinPoint对象中可以得到方法签名，从方法签名中可以得到方法这个对象，然后通过字节码信息得到OperationRecord这个注解对象，然后就是将取出的信息放到map中进行存储。注意在获取OperationRecord这个注解对象的信息时，需要对传入的参数进行解析，这里使用SpEL进行解析，具体逻辑都在getSPELValue这个方法中：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 private String getSPELValue(String speLString,JoinPoint joinPoint){ String str = null; if(StringUtils.isBlank(speLString)){ return ""; } try{ //方法中的参数解析过后的Spring表达式对象 Expression expression = parser.parseExpression(speLString); //Spring表达式的上下文对象(有哪些占位符，以及每种占位符的值) EvaluationContext context = new StandardEvaluationContext(); //获取被注解的方法 MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature(); //获取被注解的方法的形参 Object[] args = joinPoint.getArgs(); //获取运行时参数的名称 String[] parameterNames = parameterNameDiscoverer.getParameterNames(methodSignature.getMethod()); for(int i=0;i<parameterNames.length;i++){ context.setVariable(parameterNames[i],args[i]); } str = String.valueOf(expression.getValue(context)); log.info("【str={}】",str); }catch (Exception e){ e.printStackTrace(); } return str; }
该方法通过对传入的字符串进行解析，得到里面的Spring表达式对象，之后新建Spring表达式上下文对象，这个上下文对象中包含占位符信息以及每种占位符的值。接着我们获取到被注解的方法，并从方法中得到方法的形参，然后获取到运行时参数的名词，这种方式其实得到的只是方法中传递的参数值，对于方法中值没有传递的参数，目前还没获取，这一块等有空完善一下相关逻辑。
最后在使用的时候，只需在被使用的方法上添加类似如下的注解信息：
1 2 3 @OperationRecord(type = OperationEnum.REDPACKET,operation = "给用户id#userId;变更红包余额，相应的订单id#orderId;变动金额#changeBalance;变动类型#type;备注#remark",remark = "变更红包金额") public ResultVO changeRedPacketBalance(int userId, String orderId, double changeBalance, int type, String remark) { }
这样在调用这个changeRedPacketBalance方法的时候就会在数据表tb_operation_record中新增一条对应的记录。
参考文章：如何优雅地记录操作日志? 、使用Aop记录带参数的复杂接口日志 、搞定 SpringBoot 操作日志 。
