Feign日志接入ELK:JSON结构化与traceId链路实践
OpenFeign 的日志接入 ELK 做集中分析看起来无非是打开 DEBUG 级别、在 Filebeat 里加个采集路径的事可真动手跑一遍你会发现默认输出格式压根不是给日志管道准备的。我第一次尝试时Filebeat 的 json 解析直接报错原因也简单Feign 默认打印的是带箭头的多行文本像[OrderClient#getOrder] --- GET https://order-service/order/1001 HTTP/1.1这种东西根本没法按字段拆。后来我把 Feign 日志改造成单行 JSON再经过 Filebeat - Logstash - Elasticsearch - Kibana 这条链路跑通同一个 traceId 能快速把几个服务的日志对齐定位慢接口的时间从小时级压缩到分钟级。这篇内容就是那次改造的完整复盘适合已经或者准备上 ELK但 Feign 日志还在裸奔的团队。1. 默认日志与 ELK 需求的三个错位1.1 四种日志级别看着齐全实际能用的太少Spring Cloud OpenFeign 里有两层日志级别这个很多人会搞混。第一层是 Feign 自带的Logger.Level有四个值NONE、BASIC、HEADERS、FULL。第二层是我们熟悉的 SLF4J 级别由logging.level控制。默认情况下 Feign 的Logger.Level是NONE相当于完全闭嘴。你如果在 yml 里只写logging.level.com.example.feign.clientDEBUG发现日志一点动静都没有就是因为 Feign 自己的级别没开。把 Feign 级别调到BASIC之后能看到类似这样的输出[OrderClient#getOrder] --- GET https://order-service/order/1001 HTTP/1.1 [OrderClient#getOrder] --- HTTP/1.1 200 (25ms)这个格式对人工看一行是够的但放进 ELK 就尴尬。HEADERS和FULL会追加多行请求头、响应头和 body整个 message 变成一大坨混排文本时间戳、URL、状态码、耗时全都靠肉眼从字符串里找。只要日志量上来或者需要按下游服务聚合统计这种格式就是灾难。1.2 多行日志在采集端的解析成本被严重低估Filebeat 逐行读取日志文件时最理想的情况是每行一条独立、结构完整的记录。Feign 默认的多行输出会让 Filebeat 的 json 模式直接失效——你没法要求它把四五行文本拼成一个 JSON 对象。有人会想到用 multiline 配置把多行合并比如用---或---作为匹配开头。实话说这种方案能跑但很不稳Feign 的日志输出在不同版本里的缩进、前后缀略有差异请求体和响应体里如果恰好包含类似---的内容拼接马上错位。而且 multiline 会引入内部状态处理高吞吐日志时容易丢行或者把两个请求的日志黏在一起。我们当时的要求是“管道尽量简单宁可日志里少点内容也别让采集端做复杂猜测”。多行日志和这个要求直接冲突。所以第一步要做的不是去调 Filebeat而是把日志输出端改成单行结构化。1.3 没有关联字段的日志进 ELK 也只是移动垃圾还有个更扎心的问题Feign 默认日志里没有任何和调用链相关的信息。一个下单接口背后可能串了订单服务、支付服务、库存服务每个服务都在打 Feign 日志但每条日志之间没有共同字段。你在 Kibana 里搜到一个OrderClient#getOrder的 500 错误能确认是哪个用户请求触发的吗能顺藤摸瓜看到调用方日志吗搜不到。日志进了 ELK 却无法关联本质上只是把分散的噪音集中到了一起。所以这次改造的核心不是“把日志格式变成 JSON”而是三件事单行、结构化、带 traceId。单行解决采集问题结构化解决检索问题traceId 解决关联问题。下面从输出端开始拆。2. 输出端改造覆写 feign.Logger 产出单行 JSON2.1 为什么选择继承 Logger 而不是包装 ClientFeign 在请求发送和响应返回的完整生命周期里预留了 Logger 钩子logRequest、logResponse、logIOException。覆写这几个方法是框架官方支持的扩展方式跟 Feign 的请求执行天然耦合在一起能拿到configKey、Level、Request、Response和已经算好的elapsedTime。也有人通过自定义feign.Client来做日志这确实更底层能拦截到最原始的请求和响应但代价是你得自己处理重试、编解码前后的各种状态还要自己算耗时。和直接继承 Logger 相比属于用更复杂的手段拿同样的结果。继承 Logger 之后日志输出的时机和 Feign 内部逻辑完全一致改动面最小后续升级 Feign 版本时也更容易适配。但覆写一个继承类有个关键前提Feign 传给 Logger 的Level来自每个 FeignClient 配置的Logger.Level。如果你的某个 client 配了NONE框架连日志钩子都不会触发。所以自定义 Logger 并不是一劳永逸它依然需要和 Feign 的级别配置配合使用。2.2 请求/响应日志的字段设计与核心实现字段设计上我遵循一个原则字段本身要有业务意义并且能在 Kibana 里直接聚合。type区分请求和响应traceId串链路client对应 FeignClient 的方法标识urlPath单独拆出来方便按接口聚合query单独放避免 URL 后面拖一长串参数影响可读性。响应侧主要是status和costMs。实现如下基于 Feign 12 的 API老版本差异不大import com.fasterxml.jackson.core.JsonProcessingException; import com.fasterxml.jackson.databind.ObjectMapper; import feign.Request; import feign.Response; import org.slf4j.MDC; import java.nio.charset.Charset; import java.nio.charset.StandardCharsets; import java.util.Collection; import java.util.LinkedHashMap; import java.util.Locale; import java.util.Map; public class JsonFeignLogger extends feign.Logger { private static final ObjectMapper MAPPER new ObjectMapper(); private static final Charset UTF8 StandardCharsets.UTF_8; private final org.slf4j.Logger log org.slf4j.LoggerFactory.getLogger(feign-json); Override protected void logRequest(String configKey, Level logLevel, Request request) { MapString, Object data new LinkedHashMap(); data.put(type, feign-request); data.put(time, System.currentTimeMillis()); data.put(traceId, MDC.get(traceId)); data.put(client, configKey); data.put(method, request.httpMethod().name()); data.put(url, request.url()); java.net.URI uri java.net.URI.create(request.url()); data.put(urlPath, uri.getPath()); data.put(query, uri.getQuery()); if (logLevel.ordinal() Level.FULL.ordinal()) { data.put(reqHeaders, sanitizeHeaders(request.headers())); if (request.body() ! null request.body().length 0) { data.put(reqBody, truncate(new String(request.body(), UTF8), 2048)); } } log.info(toJson(data)); } Override protected void logResponse(String configKey, Level logLevel, Response response, long elapsedTime) { MapString, Object data new LinkedHashMap(); data.put(type, feign-response); data.put(time, System.currentTimeMillis()); data.put(traceId, MDC.get(traceId)); data.put(client, configKey); data.put(status, response.status()); data.put(costMs, elapsedTime); if (logLevel.ordinal() Level.FULL.ordinal()) { data.put(respHeaders, sanitizeHeaders(response.headers())); } log.info(toJson(data)); } private MapString, String sanitizeHeaders(MapString, CollectionString headers) { MapString, String result new LinkedHashMap(); headers.forEach((key, values) - { String lowerKey key.toLowerCase(Locale.ROOT); if (lowerKey.contains(authorization) || lowerKey.contains(cookie) || lowerKey.contains(token) || lowerKey.contains(secret)) { result.put(key, ***); } else { result.put(key, String.join(,, values)); } }); return result; } private String truncate(String body, int maxLen) { if (body null || body.length() maxLen) { return body; } return body.substring(0, maxLen) ...[truncated]; } private String toJson(MapString, Object data) { try { return MAPPER.writeValueAsString(data); } catch (JsonProcessingException e) { return ; } } }请求体的记录参考了 Feign 的 FULL 级别语义只有Level.FULL才带出 header 和 body。如果你把某个 client 配成BASIC那么输出里只有方法、路径、状态、耗时这些骨架字段日志量会小很多。sanitizeHeaders必须保留因为很多内部服务的认证信息就在 Authorization 头里裸记到 ELK等于把密钥写进日志。这属于一等一的安全问题。2.3 响应体为什么默认不记以及必须记时的思路上面代码没记录响应体是有意为之。Response.body()是个一次性流Logger 层面消费掉之后调用方拿到的可能就是空 body这会导致业务代码明明能拿到数据下游却突然解析失败。Feign 自带的 Logger 在打印 body 时有专门的缓冲处理我们自定义时候如果照搬过来得对 Response 做重建麻烦且容易踩版本差异。我的取舍是异常响应体交给ErrorDecoder去处理。Feign 允许你通过ErrorDecoder统一解码错误响应那里能拿到完整的响应流天然适合记录下游失败细节。把错误内容打到独立的 warn 日志里再配合自定义 Logger 的 status 字段排查链路一样完整。如果你确实需要把所有正常响应的 body 也进 ELK建议在feign.Client层用一个缓冲包装类把响应体先变成可重复读的字节数组再交给 Logger 处理不要在logResponse里去碰原始流。这个方案能保证不死心但会让日志量成倍上涨上线前先想清楚磁盘和 ES 写入压力能不能扛住。2.4 注册步骤Bean 注入和 SLF4J 级别的双层配置自定义 Logger 要生效需要两步。先在 Spring 容器里注册一个feign.Logger的 Bean再给 FeignClient 指定Logger.LevelConfiguration public class FeignGlobalConfig { Bean public Logger.Level feignLoggerLevel() { return Logger.Level.FULL; } Bean public feign.Logger feignLogger() { return new JsonFeignLogger(); } }注意这个配置类如果放在主类能被扫描到的地方它就是全局配置会影响所有 FeignClient。日志量敏感的场景建议用更细粒度在FeignClient(name order-client, configuration OrderClientConfig.class)里单独配一个BASIC或者FULL。同时 yml 里需要保证自定义 Logger 使用的feign-json这个 SLF4J 名称至少是 INFO 级别logging: level: feign-json: INFO feign: client: config: default: loggerLevel: basic order-client: loggerLevel: full这里是把 Feign 的Logger.Level和 SLF4J 输出级别分开控制前者决定帧框架回调 Logger 时传入的细节等级后者决定我们的 JSON 日志最终是否落到文件。两层都要有缺一个都会出现“代码看着没问题日志就是不出来”的怪现象。3. 管道端配置Filebeat 解析与 Logstash 入 ES 的落地姿势3.1 独立日志文件避免 json 解析污染结构化日志最好单独输出到一个独立文件不要和应用的其他业务日志混在一起。原因是 Filebeat 的 json 解析是逐行尝试的如果同一个文件里有普通文本日志行那些行会被打上logstash_parsing_error之类的标记日志管道里就会混入大量无意义的错误记录。我用 logback 给feign-json这个 logger 单独配了一个 RollingFileAppender每行只输出%msg%n因为toJson的结果本身就是完整的 JSONappender nameFEIGN_JSON_FILE classch.qos.logback.core.rolling.RollingFileAppender filelogs/feign.json.log/file rollingPolicy classch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy fileNamePatternlogs/feign.json.%d{yyyy-MM-dd}.%i.log/fileNamePattern maxFileSize100MB/maxFileSize maxHistory15/maxHistory /rollingPolicy encoder classch.qos.logback.classic.encoder.PatternLayoutEncoder pattern%msg%n/pattern /encoder /appender logger namefeign-json levelINFO additivityfalse appender-ref refFEIGN_JSON_FILE/ /loggeradditivityfalse很关键否则 JSON 日志会同时被复制到根 logger 的 appender变成双份写入。独立文件之后还能顺手把普通业务日志的采集和 Feign 日志的采集解耦后续任何一边出问题都不影响另一边。3.2 Filebeat 只做一件事把单行 JSON 塞进 LogstashFilebeat 配置里最省心的组合是keys_under_root加overwrite_keys。前者让 JSON 里的字段直接落到日志文档根部而不是包一层json对象后者允许覆盖 Filebeat 内置的一些字段。注意不要配置json.message_key除非你明确想把某个字段提升为 message否则它只会让原始 JSON 又多存一份白白膨胀。filebeat.inputs: - type: log enabled: true paths: - /data/logs/app/feign.json.log json.keys_under_root: true json.overwrite_keys: true json.add_error_key: true tags: [feign] encoding: utf-8 output.logstash: hosts: [logstash.example.internal:5044]不加 multiline是基于上面已经解决了多行问题的前提。这里有兄弟可能会想既然 Filebeat 支持 json 解析那我把type、traceId之类的字段都解析出来了Logstash 是不是可以省了可以如果只是让日志进 ESFilebeat 可以直接写 Elasticsearch。但实践中 Logstash 还是值得留一层后面你会需要做索引别名、字段清洗、日期解析这些放在 Logstash 里比塞在 Filebeat 配置里更灵活。3.3 Logstash 里最重要的是把 time 变成 timestampLogstash 配置看起来简单真正的坑在于timestamp。我们的 JSON 里time字段是毫秒时间戳如果不管它ES 会用 Logstash 收到日志的当前时间作为timestamp。日志采集有延迟时高并发下 Filebeat 积压很正常索引按天滚动就会错位Kibana 默认按timestamp显示时间你看到的日志时刻会晚于实际发生时刻。所以配置里必须用 date filter 把time解析成timestampinput { beats { port 5044 } } filter { if feign in [tags] { mutate { convert { time integer } } date { match [time, UNIX_MS] target timestamp } mutate { rename { time requestTimeMs } } } } output { elasticsearch { hosts [http://elasticsearch:9200] index feign-log-%{YYYY.MM.dd} } }UNIX_MS匹配的就是毫秒时间戳先 convert 成 integer再交给 date filter 解析兼容性最好。把原来的timerename 成requestTimeMs是为了保留原始毫秒值同时避免字段名和timestamp在语义上混淆。3.4 索引模板里把常用字段设置为 keyword避免聚合失效ES 动态映射有个经典的坑URL 和客户端标识这类字符串会被映射成 text keyword而 text 部分不能用于聚合和排序keyword 部分默认ignore_above为 256。URL 一旦超过 256 字符查询参数很容易做到后面部分在 keyword 字段里就是空的Kibana 里按service或urlPath做 term 聚合时会看到一堆空桶或者分桶缺失。提前给feign-log-*索引建模板把这些字段显式声明为 keyword顺便调大ignore_above{ index_patterns: [feign-log-*], template: { mappings: { properties: { type: { type: keyword }, traceId: { type: keyword }, service: { type: keyword }, client: { type: keyword }, method: { type: keyword }, urlPath: { type: keyword, ignore_above: 2048 }, query: { type: keyword, ignore_above: 2048 }, status: { type: long }, costMs: { type: long } } } } }status和costMs分别给成 long方便做 range 查询和 avg 聚合。traceId如果映射成 text你搜索traceId: abc可能因为分词拆出毫无意义的结果keyword 才是唯一正确选择。4. 链路闭环traceId 贯穿 Feign 请求与业务日志4.1 单条 JSON 日志再规整串不起来也没有意义如果只是把 Feign 日志变成 JSON其实价值只完成了一半。你依然回答不了“这个请求是从哪个入口发起的、中间经过了哪些节点、最后为什么失败”。真正让日志从“一条条独立事件”变成“一串可回溯的调用链”的是 traceId。实践中我推荐最简单的方案网关或者入口服务在接收到请求时生成一个 traceId 放入 MDC之后所有服务在日志输出时都带上这个 traceId。Feign 调用下游时通过请求头把 traceId 传递过去下游的过滤器再把它从请求头放回自己的 MDC。这样一条链路走下来所有日志都带着同一个 traceId。4.2 Feign 侧注入 Header 服务端接住Feign 的通用请求头注入通过RequestInterceptor最合适。因为 Spring Cloud OpenFeign 会自动收集容器里的RequestInterceptorBean并应用到每个请求上Component public class FeignTraceIdInterceptor implements RequestInterceptor { Override public void apply(RequestTemplate template) { String traceId MDC.get(traceId); if (traceId ! null !traceId.isBlank()) { template.header(X-Trace-Id, traceId); } } }下游服务需要有一个过滤器从请求头里取 traceId 并放回 MDC。这里给出一个适用 Spring Boot 3 的示例Component public class TraceIdFilter extends OncePerRequestFilter { Override protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain) throws ServletException, IOException { String traceId request.getHeader(X-Trace-Id); if (traceId null || traceId.isBlank()) { traceId java.util.UUID.randomUUID().toString().replace(-, ); } MDC.put(traceId, traceId); try { chain.doFilter(request, response); } finally { MDC.remove(traceId); } } }有了这个过滤器我们自己容器里的 Feign 自定义 Logger 里通过MDC.get(traceId)取到的 traceId就是整条调用链共用的同一个值。Kibana 里按这个值一搜A 服务的 Feign 出站日志、B 服务的入口日志、B 服务请求 C 的 Feign 日志全部按时间顺序排在一个平面内。4.3 异步线程里的 MDC 传递是经常被遗忘的角落Feign 调用如果发生在异步线程池里MDC 不会自动从主线程带过去traceId 就断了。很多微服务框架内部已经帮你处理了比如 WebFlux 的环境里有专门的上下文传播机制但如果你自己建的线程池就得手动处理。推荐的做法是给线程池配置一个TaskDecorator在提交任务时复制 MDC 上下文执行时再放回去Bean public Executor asyncExecutor() { ThreadPoolTaskExecutor executor new ThreadPoolTaskExecutor(); executor.setThreadNamePrefix(async-); executor.setQueueCapacity(1024); executor.setTaskDecorator(runnable - { MapString, String context MDC.getCopyOfContextMap(); return () - { if (context ! null) { MDC.setContextMap(context); } try { runnable.run(); } finally { MDC.clear(); } }; }); return executor; }这一条单独拎出来讲是因为链路日志断层的问题往往排查很久都找不到原因最后发现是某个异步线程里 traceId 为空。Feign 日志里traceId字段大量缺失的第一个排查点就应该是异步链路。5. 上线后的取舍与排障性能、查询模板和时区坑5.1 FULL 日志成本很高降级策略要提前定好把全部 Feign 请求的请求体和响应体都送进 ELK成本非常直接日志文件体积膨胀十倍以上Filebeat 采集压力、ES 写入压力、磁盘占用全部上涨。而且大部分请求参数的查询价值很低你很少会去翻一次 GET 请求的 header 里到底带了什么。我的习惯是默认BASIC只记录方法、路径、状态、耗时。对个别核心链路的 FeignClient 单独开FULL比如支付对账这种确实需要回看请求体的场景。如果担心线上突然出问题需要复现请求参数可以用请求日志和业务日志的关联字段兜底——我们自定义 Logger 里已经记了traceId业务日志里通常也有完整的入参不差这口 body。5.2 日志量大时的异步落盘配置Feign 是同步调用logRequest和logResponse都发生在请求执行路径上。如果日志直接同步写入磁盘每次 RPC 调用要多一次 IO 开销QPS 上来之后影响不能忽视。logback 的AsyncAppender可以解决这个问题appender nameASYNC_FEIGN_JSON classch.qos.logback.core.AsyncAppender queueSize20480/queueSize discardingThreshold0/discardingThreshold appender-ref refFEIGN_JSON_FILE/ /appender logger namefeign-json levelINFO additivityfalse appender-ref refASYNC_FEIGN_JSON/ /loggerdiscardingThreshold这个参数要提一下默认值是 -1队列满时为了不影响主流程会丢弃低级别日志可能把链路日志丢了。设成 0 表示满队列时阻塞等待保证日志不丢但极端情况下会拖慢请求线程。生产环境里我宁可选择阻塞也不丢日志因为链路日志缺失带来的排查成本远高于偶尔一次的毫秒级排队。5.3 Kibana 里最有用的几种查询姿势管道跑通、数据落库之后才知道前面所有配置值不值。Kibana 的 Discover 里我常年用这几组查询慢请求排查搜索type: feign-response AND costMs: 1000按timestamp排序再看client字段哪些接口经常进慢查询列表。错误分布搜索type: feign-response AND status: [400 TO 599]然后用client字段做 top 聚合一眼看出哪个下游服务最不稳定。全链路回溯拿到一个traceId直接搜traceId: xxxx配合时间过滤一次调用从入口到出口所有日志都出来。服务健康趋势用date_histogram聚合按小时统计status 500的数量叠加上游发布窗口能直观看出每次发版对下游依赖的影响。这些查询能成立的前提就是我们前面在索引模板里把status、costMs、client都设成了可聚合字段。如果你在 Kibana 里发现某个字段只有少数数据能用于聚合回去检查模板别只盯着采集端。5.4 跨天查询、时区、字段类型三个隐藏坑时区问题最隐蔽。ES 默认按 UTC 处理时间Kibana 的显示时区可以设置为浏览器本地或机房时区但date_histogram聚合时如果不显式指定time_zone分桶边界是 UTC 的零点你在东八区看到的新一天数据会归到前一天的分桶里。Kibana 高级设置里把dateFormat:tz改成目标时区再在可视化组件的聚合配置里加time_zone: 08:00才能对上。字段类型问题主要是 URL。动态映射下url字段的 keyword 部分默认截断 256 字符我们在模板里已经解决了。还有一个小坑是 FeignClient 的configKey是类名#方法名格式中间那个#在 Kibana 查询里需要转义或者用精确短语匹配不然容易误伤。跨天查询的问题通常伴随时区一起来Kibana 时间选择器选的是浏览器本地时间但索引按 UTC 日切凌晨零点到八点之间的日志可能落到了前一天的索引。复盘数据时如果发现某个时段的日志量明显不对先怀疑时区别急着怀疑管道丢了数据。写在最后改造收益和一些实际感受这套方案上线后最大的变化不是日志变好看了而是排障方式完全变了。以前是登到服务器上翻文件、grep 关键字、对着时间猜上下文现在一个 traceId 打到 Kibana 里请求在哪个服务上慢了、状态码是什么、耗时多少、上下游都有哪些调用一目了然。Feign 作为服务间调用的核心组件它的日志结构化是整个链路可观测性里最容易见效的一环因为它贴近每一次 RPC信息密度高格式化收益也最直接。如果你正在做类似改造我的建议是先别贪多不要一开始就要求所有 FeignClient 都上 FULL 级别。先把默认级别、JSON 输出、traceId 传递、Filebeat 独立采集跑通让数据稳定进 ES再根据实际排障需求逐步放开 body 记录。日志量失控比没有日志更可怕毕竟没人愿意为了查一个线上问题先花两天和磁盘空间做斗争。