SpringCloud OpenFeign 整合 logbook 实现链路日志

前言

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

开启 OpenFeign 日志

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

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

level 有四个等级

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

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

QQ图片20220706184803.png

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

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

logging:
  level:
    com.feign.test.client.ProductClient: DEBUG

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

logbook 简介

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

Logbook 是一个可扩展的 Java 库，可以为不同的客户端和服务器端技术启用完整的请求和响应日志记录。它通过以下方式满足了特殊需求：

允许 Web 应用程序开发人员记录应用程序接收或发送的任何 HTTP 流量，这意味着只要是 HTTP 请求它都可以选择记录日志

以一种易于持久化和分析的方式。这对于传统的日志分析、满足审计要求或调查个别历史流量问题非常有用。

具体介绍可以参考 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

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

QQ图片20220707113026.png

{
	"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

controller入口没有traceId.png

但是比较尴尬的是 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 吧......而且日志包含的字段太多也会干扰我们排查问题。

{
	"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"],
		//...省略
	}
}

我们只需要看几个关键的字段即可，例如 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 中也可能又有及其复杂的业务流程。如下图

分布式链路追踪.png

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

结语

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