Spring Cloud 微服务实践 (7) - 日志

用户头像
xiaoboey
关注
发布于: 2020 年 10 月 09 日
Spring Cloud 微服务实践(7) - 日志

记录日志是应用程序的一项基本能力,从开发测试到运维调优,以及数据安全和数据挖掘,都离不开日志的记录。本文尝试把Spring Cloud中日志相关的一些处理都梳理一下,从通用日志框架,到Gateway的访问日志(Access Log),再到基于AOP和Stream来记录业务操作日志。



1、日志框架: 从print到slf4j

说到应用程序的日志,其实是很好理解的,就Java程序来说最简单的就是System.out.println。相信很多同学都是用它来跟Java世界打的第一声招呼:

System.out.println("Hello world!");

然后从此就爱上了println,经常在代码中用它来输出一些信息。再结合String.format对输出的信息进行格式化,调试也好,找bug也好,println成了开发的好帮手。



这其实在开发阶段是没什么问题的,当部署在生产环境进行运维的时候,会有新的需求或者问题产生。比如说运维人员可能在系统一切正常的时候不想看到那么多测试输出信息,只想关注一些关键的信息和错误信息;然后在跟踪某个问题的时候,可能只想看到某个package或者某个类的输出信息;还有println是输出到console的,虽然可以重定向到文件,但是长时间运行文件会越来越大甚至超出系统支持的文件最大容量,这就需要控制日志文件的大小。



这些需求归纳起来都是每个应用的共性需求,所以在Java世界里有日志框架来应对。按照“面向接口编程,解耦具体实现”的接口隔离原则(ISP),Java开源世界前后发展出了Commons Logging、SLF4J等日志框架。这些日志框架的区别和优劣,这里不去细说。



Spring Boot默认集成的日志框架是SLF4J,日志实现是Logback。在Spring Boot项目的代码里使用SLF4J记录日志,比较简单:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class SomeClass {
private final Logger log = LoggerFactory.getLogger(this.getClass());
public SomeClass() {
log.info("Start at {}", new Date());
...
}
...
}
  • Logger是接口(interface),LoggerFactory是实例化Logger的工厂,具体实现由Spring根据应用的配置来“依赖注入”;

  • SLF4J把日志进行了分级(level),从低到高:trace(跟踪)、debug(调试)、info(信息)、warn(告警)、error(错误),可以根据日志的level来控制要输出哪些日志。比如代码里用log.trace输出的信息,在日志级别为debug时,就不会输出;

  • 上述代码里的log.info表示记录一个info级别的日志,"Start at {}"里的大括弧是占位符,实际输出时会被替换为new Date()的值;



如果开发团队用了lombok来简化代码,则是在类上加注解@Slf4j,然后代码里直接用log进行日志输出:

@Slf4j
public class SomeClass {
public SomeClass() {
log.info("Start at {}", new Date());
...
}
...
}
  • 从这里也可以看出来,为什么很多人会反对用lombok,上述代码里的log是直接蹦出来的,没有定义,影响了代码的“可读性”。



在代码里是面向接口编程,在部署时则可以用logback-spring.xml配置文件来控制日志的输出:

<?xml version="1.0" encoding="UTF-8"?>
<!-- scan: 表示运行时是否扫描配置文件的变更并重新加载,默认值为true -->
<!-- scanPeriod: scan为true时有效,表示扫描的时间间隔 -->
<!-- debug: 是否打印logback的日志信息,查看logback运行状态,默认值为false -->
<configuration scan="false" scanPeriod="60 seconds" debug="true">
<contextName>logback</contextName>
<!-- 设置变量log.home,后续配置里用${log.home}来引用 -->
<property name="log.home" value="/usr/local/spring-boot/someone/logs" />
<!--输出到控制台-->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<!-- 日志的输出格式 -->
<encoder>
<pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<!--输出到文件-->
<appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${log.home}/logback.log</file>
<!-- 滚动输出,这里是每天一个文件 -->
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${log.home}/logback.%d{yyyy-MM-dd}.log</fileNamePattern>
</rollingPolicy>
<encoder>
<pattern>%d{HH:mm:ss.SSS} %contextName [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<!-- 将日志写入MySql数据库,涉及到了JDBC驱动和连接池,在pom.xml中要做依赖的相应调整 -->
<appender name="database" class="ch.qos.logback.classic.db.DBAppender">
<connectionSource class="ch.qos.logback.core.db.DataSourceConnectionSource">
<dataSource class="org.apache.commons.dbcp.BasicDataSource">
<driverClassName>com.mysql.jdbc.Driver</driverClassName>
<url>jdbc:mysql://localhost:3306/some_log?characterEncoding=UTF-8</url>
<username>root</username>
<password>yourpwd</password>
</dataSource>
</connectionSource>
<!-- 设置日志级别 -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>info</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!--
root节点配置基础的日志输出
level:用来设置日志级别,大小写无关:TRACE,DEBUG,INFO,WARN,ERROR,ALL和OFF
-->
<root level="info">
<appender-ref ref="console" />
<appender-ref ref="file" />
<appender-ref ref="database" />
</root>
<!-- 为具体的package指定日志级别 -->
<logger name="com.example.gateway" level="info"/>
</configuration>

从配置文件logback-spring.xml可以看出,日志方面的处理,SLF4J这个日志框架都帮我们解决了。这里没有罗列所有的配置,大家可以在有具体需求时再查资料进行配置。



2、Spring MVC的Access日志

软件系统部署上线后,为了运维调优或者数据安全和数据挖掘,需要记录外部访问系统资源的情况。



在Spring Boot的WEB项目里,要记录MVC的访问日志(Access Log),有比较简便的方法,做一个简单的配置打开Web容器的访问日志记录就可以(application.yml):

server:
tomcat:
accesslog:
enabled: true
directory: d:\\logs

这里是以Tomcat为例,其他的Undertow、Jetty等都可以进行类似的配置。



输出的日志记录如下所示:

192.168.18.231 - - [29/Sep/2020:16:36:41 +0800] "GET /hello HTTP/1.1" 200 6

可以看到IP地址、访问时间、协议、方法和状态等都有了,并且这些信息和格式还可以定制。



如果要把访问日志记录到数据库里去该怎么办呢?可以解析这些日志然后入库,事实上也有一些专门做日志处理的软件来做这个事情,这里就不展开了。微服务系统里有网关,我们重点关注如何在网关去统一记录访问日志。

3、Gateway的Access日志

Spring Cloud Gateway是基于WebFlux开发,WebFlux是反应式编程,主要应对高并发场景下的服务端编程需求,异步非阻塞,跟Spring MVC的同步阻塞机制不一样。除了机制不一样,在程序的编写上也是函数式编程,对习惯了Spring MVC方式的程序员来说,需要学习和适应,有难度。



就我个人的观点,除非业务场景需要解决高并发的问题,还是不要急着上WebFlux,开发人员不好找。



回到我们的主题“日志”,Spring Cloud Gateway由于是基于WebFlux开发,已经没有WEB容器的概念了,所以不支持前面针对Tomcat开启access日志记录的那个方式。



还好Spring在设计WebFlux的时候,也延续了Spring MVC里比较好的设计模式,比如Filter。也就是有一部分概念跟Spring MVC是类似的,只是实现方式变了。所以要记录访问日志,基本的方式也是自定义一个Filter来记录:



import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.node.ObjectNode;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.cloud.gateway.filter.GlobalFilter;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.core.annotation.Order;
import org.springframework.http.HttpStatus;
import org.springframework.http.server.reactive.ServerHttpRequest;
import org.springframework.http.server.reactive.ServerHttpResponse;
@Configuration
public class GatewayGlobalFilterConfig {
private final Logger logger = LoggerFactory.getLogger(this.getClass());
private final ObjectMapper objectMapper = new ObjectMapper();
@Bean
@Order(0)
public GlobalFilter accessLogGlobalFilter() {
return (exchange, chain) -> {
long startTime = System.currentTimeMillis();
return chain.filter(exchange).doFinally((signalType) -> {
long endTime = System.currentTimeMillis();
ServerHttpRequest request = exchange.getRequest();
try {
ObjectNode node = objectMapper.createObjectNode();
node.put("path", request.getPath().value());
node.put("queryParams", objectMapper.writeValueAsString(request.getQueryParams()));
node.put("remoteAddress", request.getRemoteAddress().getHostString());
HttpStatus httpStatus = exchange.getResponse().getStatusCode();
node.put("statusName", httpStatus.name());
node.put("statusValue", httpStatus.value());
node.put("elapsedMillisecond", endTime - startTime);
logger.info(node.toString());
} catch (Exception ex) {
ex.printStackTrace();
}
});
};
}
}
  • doFinally:在整个链式处理的最后执行,记录返回的状态和消耗的时间;

  • 这里的日志信息是用logger.info进行输出,从前面日志框架(SLF4J+logback)的学习我们知道:通过在logback-spring.xml里进行配置,日志信息最后可以保存到控制台、文件或者数据库。



从上面这个Filter实现的日志记录来看,我们也可以自定义日志的记录,直接往文件或者数据库写日志数据。但是要考虑性能问题,比如写数据库的话,数据库会成为瓶颈,特别是并发访问量大的时候。logback是进行的异步处理,logger.info()这样的日志输出的耗时很少,只是把日志缓存起来,具体怎么格式化、输出到哪里,都由另外的模块来异步完成。(logback的名称原来是这么来的吗?^_^)



4、业务操作日志(Operation Log)

前面讲的都是访问日志(access log),可以记录访问了哪个URL带了什么参数。比如访问/user/delete,携带参数userId=123,结果(response)里的HttpStatus是200。这样的日志对运维等专业技术人员来说,在熟悉系统的情况下,知道是什么意思。但这样的日志如果给非专业的人看会怎么样?那肯定是看不懂的,一脸懵逼,对你这个系统的使用体验会变得极差。



所以这里提一个业务操作日志的说法,用更易懂的描述来记录日志。比如刚才那个/user/delete的例子,业务日志就记录为“删除了编号为123的用户”。记录业务操作日志比记录访问日志要麻烦,访问日志(Access Log)我们在Gateway上统一记录就可以了,业务操作日志记录的内容则是跟具体的业务有关,所以要在业务实现的地方去记录。



业务日志的记录分散到了系统的各个地方,但是跟具体的业务实现又无关,所以非常适合用AOP来实现。AOP(Aspect Oriented Programming,面向切面编程)在不改变程序原有逻辑的基础上,增加一些额外的功能,是对OOP(Object Oriented Programming,面向对象编程)的补充和完善。OOP的封装、继承、多态建立了对象的层次机构,AOP则是“横切”对象,把一些分散到各处的公共调用逻辑封装起来,减少了重复代码,降低了模块之间的耦合度,方便开发和维护。



AOP是Spring的主要特性之一,我们平常的Spring开发中也大量用到了用AOP开发的功能,比如数据库事务管理,可以在类上添加注解@Transactional来声明式地管理事务,而具体的事务处理则是统一由Spring框架去完成。所以说AOP只是一种编程思想,具体到Java语言最后还是落在注解(Annotation)和反射(Reflection)上来实现AOP的思想。



现在我们就用AOP的思想来实现业务操作日志的记录,先实现一个自定义注解:

package com.example.serviceone.log;
import java.lang.annotation.*;
@Target(ElementType.METHOD) //注解位置,METHOD表示注解在方法上
@Retention(RetentionPolicy.RUNTIME) //运行时执行
@Documented
public @interface OperationLog {
String module() default "";
String operation() default "";
String details() default "";
}

再创建一个切面类来执行业务日志的记录:

import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.node.ObjectNode;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.core.LocalVariableTableParameterNameDiscoverer;
import org.springframework.expression.ExpressionParser;
import org.springframework.expression.spel.standard.SpelExpressionParser;
import org.springframework.expression.spel.support.StandardEvaluationContext;
import org.springframework.stereotype.Component;
import org.springframework.util.StringUtils;
import org.springframework.web.context.request.RequestAttributes;
import org.springframework.web.context.request.RequestContextHolder;
import javax.servlet.http.HttpServletRequest;
import javax.validation.constraints.NotNull;
import java.lang.reflect.Method;
import java.util.Map;
@Aspect
@Component
public class OperationLogAspect {
private final Logger logger = LoggerFactory.getLogger(this.getClass());
private final ObjectMapper objectMapper = new ObjectMapper();
/**
* 设置业务操作日志切入点: 在加了自定义注解OperateLog的地方切入代码
*/
@Pointcut("@annotation(com.example.serviceone.log.OperationLog)")
public void operateLogPointCut() {
}
/**
* 环绕执行,即切点前后执行
* @param joinPoint
* @return
* @throws Throwable
*/
@Around(value = "operateLogPointCut()")
public Object saveOperationLog(ProceedingJoinPoint joinPoint) throws Throwable {
RequestAttributes requestAttributes = RequestContextHolder.getRequestAttributes();
HttpServletRequest request = (HttpServletRequest) requestAttributes.resolveReference(RequestAttributes.REFERENCE_REQUEST);
Map<String, String[]> parameterMap = request.getParameterMap();
MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
Method method = methodSignature.getMethod();
String methodName = method.getName();
long startTime = System.currentTimeMillis();
Object result = joinPoint.proceed();
ObjectNode node = objectMapper.createObjectNode();
node.put("path", request.getRequestURI());
node.put("queryParams", objectMapper.writeValueAsString(parameterMap));
node.put("remoteAddress", request.getRemoteAddr());
OperationLog operationLog = method.getAnnotation(OperationLog.class);
if (operationLog != null) {
node.put("module", operationLog.module());
node.put("operation", operationLog.operation());
String details = operationLog.details();
if (!StringUtils.isEmpty(details)) {
details = parseDetails(details, method, joinPoint.getArgs());
}
node.put("details", details);
}
String className = joinPoint.getTarget().getClass().getName();
node.put("className", className);
node.put("methodName", methodName);
long endTime = System.currentTimeMillis();
node.put("elapsedMillisecond", endTime - startTime);
logger.info(node.toString());
//写入数据库
...
return result;
}
/**
* 异常处理
* @param joinPoint
* @param e
*/
@AfterThrowing(pointcut = "operateLogPointCut()", throwing = "e")
public void saveExceptionLog(JoinPoint joinPoint, Throwable e) {
...
}
/**
* 解析Spring EL表达式
* @param details
* @param method
* @param args
* @return
*/
private String parseDetails(@NotNull String details, Method method, Object[] args) {
LocalVariableTableParameterNameDiscoverer discoverer = new LocalVariableTableParameterNameDiscoverer();
String[] parameterNames = discoverer.getParameterNames(method);
ExpressionParser parser = new SpelExpressionParser();
StandardEvaluationContext context = new StandardEvaluationContext();
for (int i = 0; i < parameterNames.length; i++) {
context.setVariable(parameterNames[i], args[i]);
}
return parser.parseExpression(details).getValue(context, String.class);
}
}



在需要记录操作日志的Controller方法上添加注解@OperationLog

@OperationLog(module = "测试", operation = "删除用户", details = "'用户编号:' + #userId")
@RequestMapping("/user")
public String deleteUser(@RequestParam int userId) {
...
}

注:@OperationLog注解的details参数使用了Spring表达式(EL),最后记录的日志里#userId会被替换为传入参数userId的具体值。

5、消息驱动的日志记录(Spring Cloud Stream)

在微服务系统里,我们再来看一下logback日志的异步处理方式,它只是在某一个微服务上进行了异步,如果分布式部署大量的微服务都用logback记录日志到数据库,对数据库的压力还是很大的。所以这里我们结合Spring Cloud Stream,用消息驱动的方式来记录日志。



消息驱动其实在日常生活中的例子比较多,就拿打电话和发短信来说,打电话是在线模式,通话双方接通后的沟通是即时的,是你一句我一句的应答,这时有其他电话进来就会“占线”,这跟我们顺序执行的程序比较类似,同步阻塞;发短信则是异步的,不要求对方在线,对方甚至可以关机,发送方只管把消息发送出去,然后去忙其他的事情,接收方可以慢慢来处理这些消息,异步非阻塞。



所以消息驱动的优点就是:

  • 异步处理,异步是提高系统效率的法宝,并且异步往往是跟并行处理相关的,比如你打印一份页数比较多的文件,打印任务给到打印机后,你可以看看邮件什么的做点其他的事情,等打印完毕再去整理装订;

  • 应用解耦,回想一下前面我们讲到的微服务之间的相互调用,如果服务调用不返回结果只是去触发其他服务的某个操作,这种情况是适合用消息驱动来解耦的;

  • 流量削峰,并发请求量大的时候,消息系统可以缓解并发压力,可能有的消息处理没那么及时,但终归都会完成处理,不会让系统在高压下失去响应甚至崩溃。



回到本文讨论的日志记录,在微服务系统里大量的细粒度服务在并行运行,如果都往数据库里写业务操作日志,势必对数据库造成很大的压力。为了减少数据库的压力,我们引入消息系统并采用消息驱动的方式来记录日志:业务系统产生日志信息后发送消息到消息系统,然后由专门的日志记录微服务来接收消息并写入数据库;这样我们的日志产生(Producer生产者)和日志记录(Cosumer消费者)就是异步处理的,并降低了耦合度,只需要定义好日志消息的格式;并且在日志量大的时候,可以借助消息系统的能力来堆积消息,缓解日志记录和数据库的压力。



Spring Cloud Stream对具体的消息中间件进行了封装(目前主要是RabbitMQ和Kafka),提供了一个统一的消息驱动编程模型。基于这个编程模型进行开发,可以降低切换消息中间件的成本。当然这个统一的编程模型也牺牲了具体消息中间件的特性,就跟JDBC一样,大部分情况下可以用统一的模型来开发,但是一些特殊情况还是需要针对具体的消息中间件来特殊处理。



RabbitMQ擅长消息路由,Kafka则是大数据量的流处理,所以这里选择Kafka做消息中间件。Kafka的安装这里就不赘述了,请大家找资料安装一下,建议用Docker容器的方式安装。



先实现消息的发送(Producer,生产者),添加Maven依赖(pom.xml):

<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-starter-stream-kafka</artifactId>
</dependency>



修改应用配置(application.yml):

spring:
...
cloud:
stream:
kafka:
binder:
#kafka消息中间件的地址和端口,多个用逗号分隔
brokers: 192.168.18.231:8092
#跟后面的partition-count配合自动增加消息发分区
auto-add-partitions: true
bindings:
operation-log-output:
destination: operation.log.messages
content-type: application/json
producer:
partition-count: 2



实现一个自定义的Stream消息通道接口:

import org.springframework.cloud.stream.annotation.Output;
import org.springframework.messaging.MessageChannel;
public interface IOperationLogOutput {
//对应application.yml中的spring.cloud.stream.bindings.operation-log-output
String OUTPUT = "operation-log-output";
@Output(IOperationLogOutput.OUTPUT)
MessageChannel output();
}



发送消息:

import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.node.ObjectNode;
import org.springframework.cloud.stream.annotation.EnableBinding;
import org.springframework.messaging.support.MessageBuilder;
import org.springframework.stereotype.Service;
@Service
@EnableBinding(IOperationLogOutput.class)
public class OperationLogOutputService {
private final IOperationLogOutput logOutput;
public OneOutputService(IOperationLogOutput logOutput) {
this.logOutput = logOutput;
}
public void sendMsg(ObjectNode msgNode) {
this.logOutput.output().send(MessageBuilder.withPayload(msgNode).build());
}
}

:从代码来看,基于Spring Cloud Stream提供的统一编程模型来开发消息推送,确实很简单。



接下来看看消息接收的代码,Maven依赖跟消息发送是一样的,消费者(Consumer)的配置(application.yml):

spring:
...
cloud:
stream:
kafka:
binder:
brokers: 192.168.18.231:8092
bindings:
operation-log-input:
consumer:
#auto-bind-dlq: true
#requeue-rejected: true
concurrency: 1
max-attempts: 1
auto-commit-offset: false
bindings:
operation-log-input:
destination: operation.log.messages
#一条消息只会被组里的某个微服务实例消费一次,如果不设置组,则一个实例会消费所有的消息
group: ${spring.application.name}



同样需要定义消息订阅通道:

import org.springframework.cloud.stream.annotation.Input;
import org.springframework.messaging.SubscribableChannel;
public interface IOperationLogInput {
String INPUT = "operation-log-input";
@Input(IOperationLogInput.INPUT)
SubscribableChannel input();
}



接收消息:

import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.ObjectMapper;
import org.springframework.cloud.stream.annotation.EnableBinding;
import org.springframework.cloud.stream.annotation.StreamListener;
import org.springframework.kafka.support.Acknowledgment;
import org.springframework.kafka.support.KafkaHeaders;
import org.springframework.messaging.handler.annotation.Header;
@EnableBinding(IOperationLogInput.class)
public class OperationLogInputService {
private final long sleep = 10000L;
@StreamListener(value = IOperationLogInput.INPUT)
public void input(String payload, @Header(KafkaHeaders.ACKNOWLEDGMENT) Acknowledgment acknowledgment, @Header(KafkaHeaders.OFFSET) Long offset) {
ObjectMapper mapper = new ObjectMapper();
try {
JsonNode node = mapper.readTree(payload);
//保存日志到数据库
...
//这里结合application.yml的配置auto-commit-offset=false进行手工提交,保证每条消息都被消费
acknowledgment.acknowledge();
} catch (JsonProcessingException e) {
e.printStackTrace();
//拒绝消息,要求消息系统延时重试
acknowledgment.nack(sleep);
}
}
}



消息驱动的日志记录就完成了,其实可以不是日志的处理,其他适合消息驱动的应用场景都可以这样用。

6、总结

本文从简单的println到引入了消息中间件的Spring Cloud Stream,围绕日志记录讲了多种处理方式,具体采用哪种方式,还得具体问题具体分析,活学活用。我的建议是够用就行,不要过度设计。



上一篇: Spring Cloud 微服务实践 (6) - 资源服务器

下一篇: Spring Cloud 微服务实践 (8) - 部署

发布于: 2020 年 10 月 09 日 阅读数: 53
用户头像

xiaoboey

关注

IT老兵 2020.07.20 加入

资深Coder,爱好钓鱼逮鸟。

评论

发布
暂无评论
Spring Cloud 微服务实践(7) - 日志