SpringCloud OpenFeign 整合 logbook 实现链路日志

迈不过友情╰ 2024-03-24 11:21 21阅读 0赞

### 前言 ###

工作中我们有些生产问题出现在微服务 `OpenFeign` 的互相调用中，然而 `OpenFeign` 的调用默认是不打日志的。这给我们线上排查问题带来很大的阻力。

### 开启 OpenFeign 日志 ###

我们还是选择使用配置类开启日志打印

@Configuration
    public class FeignLoggerConfiguration {
        @Bean
        Logger.Level feignLoggerLevel() {
            return Logger.Level.FULL;
        }
    }
    复制代码

`level` 有四个等级

*  `NONE` 不打日志，默认值
 *  `BASIC` 只记录 method、url、响应码，执行时间
 *  `HEADERS` 只记录请求和响应的 header
 *  `FULL` 全部都记录

我们可以查看一下 FULL 等级时的日志效果。

![format_png][]

可以看到日志内容相对来说还是很详细的，大体上是满足了线上排查 bug 的需求。

值得注意的是 Feign 的日志级别默认是 debug ，所以我们要配置 `FeignClient` 包的日志级别

logging:
      level:
        com.feign.test.client.ProductClient: DEBUG
    复制代码

但它是专门用于 `OpenFeign` 的跨服务调用，不太方便能和我们系统内部的业务日志结合，于是我们可以引入另一个组件 `logbook`。

### logbook 简介 ###

很多人可能没有接触过 `logbook`，但它的确是一个很好用的日志框架。引用官网的介绍

> **Logbook** 是一个可扩展的 Java 库，可以为不同的客户端和服务器端技术启用完整的请求和响应日志记录。它通过以下方式满足了特殊需求：
> 
>  *  允许 Web 应用程序开发人员记录应用程序接收或发送的任何 HTTP 流量 ，这意味着只要是 HTTP 请求它都可以选择记录日志
>  *  以一种易于持久化和分析的方式。这对于传统的日志分析、满足审计要求或调查个别历史流量问题非常有用。

具体介绍可以参考 [logbook 官网][logbook]

`Feign.Logger` 只是 `Feign` 组件中一个小功能，而 `logbook` 是一个专业的日志处理框架，很明显它们没有可比性。下面我们来感受一下 `logbook` 组件，它的功能要强大的多。

### 使用 logbook ###

`logbook` 官方提供了 `logbook-spring-boot-starter` ，引入依赖

implementation("org.zalando:logbook-okhttp:2.5.0")
    implementation ("org.zalando:logbook-spring-boot-starter:2.5.0")
    复制代码

`logbook` 需要配置日志级别为 `TRACE`，application.yml 中

logging:
      level:
        org.zalando.logbook: TRACE
    复制代码

然后写个测试接口，我们可以看到日志

![format_png 1][]

{
    	"origin": "remote", #remote 代表远程请求，local 代表本地发出的请求 例如 Feign
    	"type": "request",
    	"correlation": "b2b2b8e449d7b650", #请求唯一id
    	"protocol": "HTTP/1.1",
    	"remote": "0:0:0:0:0:0:0:1",
    	"method": "GET",
    	"uri": "http://localhost:8080/consumer",
    	"headers": {
    		"accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],
    		"accept-encoding": ["gzip, deflate, br"],
    		"accept-language": ["zh-CN,zh;q=0.9"],
    		"cache-control": ["max-age=0"],
    		"connection": ["keep-alive"],
    		"host": ["localhost:8080"],
    		//...省略
    	}
    }
    复制代码

{
    	"origin": "local",
    	"type": "response",
    	"correlation": "b2b2b8e449d7b650",
    	"duration": 3022, # 响应时长
    	"protocol": "HTTP/1.1",
    	"status": 200,
    	"headers": {
    		"Connection": ["keep-alive"],
    		"Content-Type": ["application/json"],
    		"Date": ["Thu, 07 Jul 2022 03:18:38 GMT"],
    		"Keep-Alive": ["timeout=60"],
    		"Transfer-Encoding": ["chunked"]
    	},
    	"body": "2022-07-07T03:18:38.248+00:00"
    }
    复制代码

问题来了，上面只看到了 `Controller` 的请求和响应日志，却没有打印 `Feign` 的调用日志。这是因为 `Feign` 没有添加 `LogbookInterceptor` 拦截器，而 `Feign` 默认只提供了一个鸡肋的 `FeignRequestInterceptor`，所以想给 `Feign` 添加拦截器我们可以从 `OkHttp` 上面想办法。

#### OpenFeign 开启 OkHttp ####

对于 OkHttp 就不多介绍了，据说 OkHttp 相比 HttpClient 有更好的性能提升 ，Feign 官方提供了直接一键切换 OkHttp 的配置

feign:
      okhttp:
        enabled: true #使用 OKHTTP
      httpclient:
        enabled: false
    复制代码

引入 OkHttp 依赖，

implementation ("com.squareup.okhttp3:okhttp:4.9.0")
    implementation ("io.github.openfeign:feign-okhttp:10.12")
    复制代码

这样依赖 `Feign` 的调用就会走 `OkHttpClient`，下面我们给 `OkHttpClient` 添加 `logbook` 拦截器

@Configuration
    public class FeignOkHttpClientConfiguration {
      @Bean
      public OkHttpClient.Builder okHttpClientBuilder(Logbook logbook) {
        return new OkHttpClient.Builder().addNetworkInterceptor(new LogbookInterceptor(logbook));
      }
    }
    复制代码

再次测试请求查看日志发现 `Feign` 的调用日志被完整打印出来

#### 选择日志风格 ####

`logbook` 提供了多种日志风格，默认是 `JSON` ，在 application.yml 中通过以下配置选择

logbook:
      format:
        style: json #默认值，可选值还有 curl、http、splunk
    复制代码

#### 添加 traceId ####

通常我们在 ELK 等日志搜集平台上需要查询一个请求链路的完整日志来便于排查问题，不然生产环境那么多日志，我们如何区分哪些日志是我们这次请求的呢？

最简单的场景就是一个接口响应非常慢，我们通过完整的链路日志就能具体定位到到底是哪一个方法甚至是哪一行代码执行的很慢。

这时候我们需要给当前请求一个唯一的链路标识 `traceId`，搜索日志的时候我们用 `traceId` 来筛选，就可以查到当前这次请求相关的所有日志，然后仔细排查问题。

`SpringBoot` 默认使用 `logback` 日志框架，我们引入 `lombok` 使用 `Slf4j` 这个简单的日志外观模式操作 `logback` 即可。使用 `Slf4j` 的 `MDC` 类在过滤器中添加 `traceId`

@WebFilter(urlPatterns = "/*")
    public class TraceIdFilter extends OncePerRequestFilter {
        @Override
        protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
            MDC.put("traceId", UUID.randomUUID().toString());
            filterChain.doFilter(request, response);
        }
    }
    复制代码

然后根据模板写一个 logback-sprng.xml 文件

<?xml version="1.0" encoding="UTF-8"?>
    <configuration>
        <property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%-5level] [%thread] [traceId=%X{traceId:-}]    [%logger] [%F:%L] %msg%n"/>
            
            <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
                <layout class="ch.qos.logback.classic.PatternLayout">
                    <Pattern>${LOG_PATTERN}</Pattern>
                </layout>
            </appender>
            <root level="INFO">
                <appender-ref ref="console"/>
            </root>
    </configuration>
    复制代码

之后我们再次请求接口测试，发现请求链路有 traceId

![format_png 2][]

但是比较尴尬的是 `Controller` 入口的请求没有 `traceId`，这是因为 `logbook` 的过滤器优先级最高，它打印请求日志时，代码还没有请求到我们自定义的过滤器，`MDC` 里面还没有设置 `traceId`，所以我们需要从 `logbook` 入手，其实 `logbook` 日志中的 `correlation` 就是唯一标识，每次请求都会生成一个，我们可以使用它作为 `traceId`，向 `Spring` 注入 `CorrelationId` 时就手动设置 `traceId`，这样就能保证整个链路上都有 `traceId`。

@Configuration
    public class LogbookConfiguration {
        
      @API(status = INTERNAL)
      @Bean
      public CorrelationId correlationId() {
        return request -> {
          if (request.getOrigin() == Origin.LOCAL) { // 说明是 feign 发出的请求，不要覆盖 traceId
            return MDC.get("traceId");
          }
          String traceId = UUID.randomUUID().toString().replace("-", "");
          MDC.put("traceId", traceId);
          return traceId;
        };
      }
    }
    复制代码

这样再次测试发现整个链路都有 `traceId` 了。此时我们不再需要前面的 `TraceIdFilter` 。

#### 敏感字段加密 ####

通常用户的敏感字段，例如手机号、身份证号码、银行卡号等，我们并不希望暴露在日志系统上，这时我们可以对敏感字段加密或者隐藏。`logbook` 提供了多个 `filter` 来过滤 `header、query、request、response` 等。而这些逻辑默认已经定义好了，我们只需要配置需要混淆的字段名即可

logbook:
      obfuscate: # 混淆
        headers: host,accept # 例如我们混淆请求主机
        parameters: phone
        paths: xx
    复制代码

之后再次测试发现日志中相关字段已经被替换成 `XXX` 。当然如果默认功能不够用，我们可以自己定义相关 `filter` 的 `Bean` 覆盖默认配置即可，非常简单。

#### 剔除多余的日志字段 ####

你可能已经发现了，这框架功能是挺强大的，但是也挺啰嗦的，看下面这段请求日志有很多我们并不需要看的东西，基本上我们不会关心那一堆没用的 `header` 吧......而且日志包含的字段太多也会干扰我们排查问题。

我们只需要看几个关键的字段即可，例如 `type、remote、method、uri` 几个固定的 header 。那么我们怎么去删减一些不需要看的字段呢？

其实对于已实现的 `starter` 进行功能更改是一件很简单的事情，因为我们都知道它是向 `Spring` 注入了相关 `Bean` ，然后有自己的实现，那么我们只需要找到原本的实现类，重写实现方法，把我们自己的实现类注入到 `Spring` 即可。

通过 debug 我们发现 `logbook` 使用的是 `HttpLogFormatter` 类型的格式化器，源码中

@API(status = INTERNAL)
    @Bean
    @ConditionalOnBean(ObjectMapper.class)
    @ConditionalOnMissingBean(HttpLogFormatter.class)
    public HttpLogFormatter jsonFormatter(
            @SuppressWarnings("SpringJavaInjectionPointsAutowiringInspection") final ObjectMapper mapper) {
        return new JsonHttpLogFormatter(mapper);
    }
    复制代码

那么我们现在参考原有的，来自己定义格式化器放入 `Spring` 容器，重写格式化方法即可。首先定义一个配置，用来配置我们需要展示哪些字段

@ConfigurationProperties(prefix = LogbookFieldExcludeProperties.PREFIX)
    @Component
    @Data
    public class LogbookFieldExcludeProperties {
      public static final String PREFIX = "logbook.field.include";
      private List<String> header;
    }
    复制代码

然后实现子接口 `StructuredHttpLogFormatter` 重写 `format` 等相关方法

@Configuration
    public class JsonHttpLogFormatterConfiguration implements StructuredHttpLogFormatter {
      @Autowired private LogbookFieldExcludeProperties properties;
      private final ObjectMapper mapper;
    
      public JsonHttpLogFormatterConfiguration(ObjectMapper mapper) {
        this.mapper = mapper;
      }
    
      /** 格式化请求 */
      @Override
      public String format(Precorrelation precorrelation, HttpRequest request) throws IOException {
        final Map<String, Object> content = new LinkedHashMap<>();
        content.put("origin", request.getOrigin().name().toLowerCase(Locale.ROOT));
        content.put("type", "request");
        content.put("remote", request.getRemote());
        content.put("method", request.getMethod());
        content.put("uri", request.getRequestUri());
    
        prepareHeaders(request).ifPresent(headers -> content.put("headers", headers));
        prepareBody(request).ifPresent(body -> content.put("body", body));
    
        return format(content);
      }
    
    /** 剔除多余 header 的逻辑 */
      @Override
      public Optional<Map<String, List<String>>> prepareHeaders(HttpMessage message) {
        final Map<String, List<String>> headers = message.getHeaders();
    
        Map<String, List<String>> map = new HashMap<>(headers);
        map.entrySet().removeIf(e -> !properties.getHeader().contains(e.getKey()));
        return Optional.ofNullable(map.isEmpty() ? null : map);
      }
    
      /** 格式化响应，和 request 几乎一样 */
      @Override
      public String format(Correlation correlation, HttpResponse response) throws IOException {
        final Map<String, Object> content = new LinkedHashMap<>();
    
        content.put("origin", response.getOrigin().name().toLowerCase(Locale.ROOT));
        content.put("type", "response");
        content.put("status", response.getStatus());
        content.put("duration", correlation.getDuration().toMillis());
        prepareHeaders(response).ifPresent(headers -> content.put("headers", headers));
        prepareBody(response).ifPresent(body -> content.put("body", body));
        return format(content);
      }
    
      @Override
      public String format(Map<String, Object> content) throws IOException {
        return mapper.writeValueAsString(content);
      }
    }
    复制代码

然后测试接口查看日志，是不是简洁的多呢？

{
    	"origin": "remote",
    	"type": "request",
    	"remote": "0:0:0:0:0:0:0:1",
    	"method": "GET",
    	"uri": "http://localhost:8080/consumer",
    	"headers": {
    		"host": ["localhost:8080"]
    	}
    }
    复制代码

### 整合分布式链路追踪 ###

上面我们已经实现了在一个单体应用中实现一个完整的请求链路日志，包括 `Feign` 的请求和响应日志，但是在上述实现方案的微服务中我们由服务 A 调用服务 B ，那么我们其实只是得到了 A 调用 B 这一个方法的初始请求日志和最终结果日志，但是你知道 B 服务的方法中又经历了哪些链路吗？比如 B 服务的方法中甚至还可能调用了服务 C 和服务 D，服务 C 和 D 中也可能又有及其复杂的业务流程。如下图

![format_png 3][]

我们现在只实现了上图 服务A 的完整链路请求，对于后续的下游服务是没有实现的，这个就需要用分布式链路追踪。篇幅有限，这个等写到分布式链路追踪组件时会专门出一篇文章。

### 结语 ###

本篇文章简单介绍了 `OpenFeign` 的日志开启，以及使用 `logbook` 去完善我们常用的日志需求。`logbook` 还有很多其他特性有兴趣可以自己研究。

[format_png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/56327cc4655c4395972186933ae58d51.png
[logbook]: https://link.juejin.cn?target=https%3A%2F%2Fgithub.com%2Fzalando%2Flogbook
[format_png 1]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/bf2de6a629a940489436a96f47e31b65.png
[format_png 2]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/8986b57c6c0243f29a5d474f135ba055.png
[format_png 3]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/38d7b57137b649538bd473b165a7338f.png