Spring Boot Sping Boot 3微米迹线和量程ID未传播到控制器外部

vlju58qv  于 2023-04-20  发布在  Spring
关注(0)|答案(1)|浏览(115)

我们正在从Sping Boot 2.x和Spring Cloud Sleuth转向Spring Boot 3.x和Micrometer跟踪。我们只对trace和span ID感兴趣,至少目前我们对可观察性不感兴趣。
在Sleuth或多或少开箱即用的情况下,由于一些奇怪的原因,使用Micrometer时,跟踪和span ID不会在@RestController之外记录。其他组件在单独的库中,负责将所有请求记录到RabbitMQ,设置OAuth2资源服务器等。由于这些库,我不能提供最小的示例。无论如何,一个最小的例子就可以了,但是产品代码不行。
除了application.yml文件中的属性之外,没有进行任何配置,其相关内容如下所示:

logging:
  level:
    root: INFO
  pattern:
    level: "%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]"
management:
  endpoints:
    web:
      exposure:
        include: "*"
  tracing:
    sampling:
      probability: 1.0
    propagation:
      type: b3
  metrics:
    distribution:
      percentiles-histogram:
        greeting: true
        http:
          server:
            requests: true

我写了一个小的Sping Boot 2服务,它只会使用Sleuth将所有请求传递给Spring Boot 3服务。它的输出是这样的(为了匿名而编辑了一点):

2023-04-12 08:43:22.855 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] INFO LNVPF1B8UCP [http-nio-8080-exec-1] org.apache.juli.logging.DirectJDKLog - Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-04-12 08:43:22.855 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] INFO LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.web.servlet.FrameworkServlet - Initializing Servlet 'dispatcherServlet'
2023-04-12 08:43:22.857 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] INFO LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.web.servlet.FrameworkServlet - Completed initialization in 2 ms
2023-04-12 08:43:22.874 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] INFO LNVPF1B8UCP [http-nio-8080-exec-1] ny.company.utils.springrest.filters.LoggingFilter - UUID: [5457319f-7310-42de-a5a7-0230f8ffcf5c] - Received [HTTP/1.1] [GET] on URL [http://localhost:8080/productStock?sku=HLD007353] from physical IP [0:0:0:0:0:0:0:1] and XFF IP [0:0:0:0:0:0:0:1]. Content-Type [null] and Content-Length [-1].
2023-04-12 08:43:22.887 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] DEBUG LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.security.web.FilterChainProxy - Securing GET /productStock?sku=HLD007353
2023-04-12 08:43:22.893 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] DEBUG LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.security.web.context.SecurityContextPersistenceFilter - Set SecurityContextHolder to empty SecurityContext
2023-04-12 08:43:23.277 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] DEBUG LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.security.oauth2.server.resource.authentication.JwtAuthenticationProvider - Authenticated token
2023-04-12 08:43:23.280 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] DEBUG LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.security.oauth2.server.resource.web.BearerTokenAuthenticationFilter - Set SecurityContextHolder to JwtAuthenticationToken [Principal=org.springframework.security.oauth2.jwt.Jwt@b27352b4, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=0:0:0:0:0:0:0:1, SessionId=null], Granted Authorities=[SCOPE_profile email, ROLE_offline_access, ROLE_uma_authorization, ROLE_default-roles-phoenix, ROLE_role_stock:read, ROLE_manage-account, ROLE_view-profile, ROLE_manage-account-links]]
2023-04-12 08:43:23.293 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] DEBUG LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.security.access.intercept.AbstractSecurityInterceptor - Authorized filter invocation [GET /productStock?sku=HLD007353] with attributes [permitAll]
2023-04-12 08:43:23.294 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] DEBUG LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.security.web.FilterChainProxy$VirtualFilterChain - Secured GET /productStock?sku=HLD007353
2023-04-12 08:43:24.524 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] DEBUG LNVPF1B8UCP [http-nio-8080-exec-1] org.springframework.security.web.context.SecurityContextPersistenceFilter - Cleared SecurityContextHolder to complete request
2023-04-12 08:43:24.533 [test-service,6c93335d5b0e4a9c,6c93335d5b0e4a9c,] INFO LNVPF1B8UCP [http-nio-8080-exec-1] my.company.utils.springrest.filters.LoggingFilter - UUID: [5457319f-7310-42de-a5a7-0230f8ffcf5c] - HTTP Request complete. Response with status code [200], Content-Type [application/json] and Content-Length [2197].

所以trace ID和span ID显示正确。但是,Sping Boot 3服务的所有部分都缺少它们:

2023-04-12T08:43:24.258+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : ---- FILTER ----
2023-04-12T08:43:24.258+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : accept-encoding: gzip
2023-04-12T08:43:24.258+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : user-agent: ReactorNetty/1.0.18
2023-04-12T08:43:24.258+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : host: localhost:8081
2023-04-12T08:43:24.259+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : accept: */*
2023-04-12T08:43:24.259+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : authorization: Bearer (redacted)
2023-04-12T08:43:24.259+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : x-b3-traceid: 6c93335d5b0e4a9c
2023-04-12T08:43:24.259+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : x-b3-spanid: 253051e75ac78374
2023-04-12T08:43:24.259+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : x-b3-parentspanid: 6c93335d5b0e4a9c
2023-04-12T08:43:24.259+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : x-b3-sampled: 0
2023-04-12T08:43:24.259+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : traceparent: 00-00000000000000006c93335d5b0e4a9c-253051e75ac78374-00
2023-04-12T08:43:24.260+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : Received [HTTP/1.1] [GET] on URL [http://localhost:8081/productStock?sku=HLD007353] from physical IP [127.0.0.1] and XFF IP [127.0.0.1]. Content-Type [null] and Content-Length [-1].
2023-04-12T08:43:24.334+02:00  INFO [stock-management-service,6c93335d5b0e4a9c,eece83b9a11ddd20] 19504 --- [nio-8081-exec-4] m.c.stock.web.StockManagementController  : Received request: SKU=HLD007353, serial=null, channel=null
2023-04-12T08:43:24.354+02:00  INFO [stock-management-service,6c93335d5b0e4a9c,eece83b9a11ddd20] 19504 --- [nio-8081-exec-4] m.c.stock.web.StockManagementController  : Returned 4 result(s):
2023-04-12T08:43:24.354+02:00  INFO [stock-management-service,6c93335d5b0e4a9c,eece83b9a11ddd20] 19504 --- [nio-8081-exec-4] m.c.stock.web.StockManagementController  :   Product=Samsung Galaxy A40 DS Black, serial=354878110668408, price=249.0
2023-04-12T08:43:24.354+02:00  INFO [stock-management-service,6c93335d5b0e4a9c,eece83b9a11ddd20] 19504 --- [nio-8081-exec-4] m.c.stock.web.StockManagementController  :   Product=Samsung Galaxy A40 DS Black, serial=354878110139996, price=249.0
2023-04-12T08:43:24.354+02:00  INFO [stock-management-service,6c93335d5b0e4a9c,eece83b9a11ddd20] 19504 --- [nio-8081-exec-4] m.c.stock.web.StockManagementController  :   Product=Samsung Galaxy A40 DS Black, serial=354878110674786, price=249.0
2023-04-12T08:43:24.355+02:00  INFO [stock-management-service,6c93335d5b0e4a9c,eece83b9a11ddd20] 19504 --- [nio-8081-exec-4] m.c.stock.web.StockManagementController  :   Product=Samsung Galaxy A40 DS Black, serial=354878110674893, price=249.0
2023-04-12T08:43:24.359+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.u.springrest.filters.LoggingFilter   : HTTP Request complete. Response with status code [200], Content-Type [application/json] and Content-Length [1757].
2023-04-12T08:43:24.360+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.s.a.l.services.SecurityAuditService  : Sending security Audit Message to exchange [vf.iss.appsec.x] and routing key [vf.iss.appsec.q].
2023-04-12T08:43:24.362+02:00  WARN [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.s.a.l.services.SecurityAuditService  : Trace ID is empty
2023-04-12T08:43:24.366+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.s.a.l.services.SecurityAuditService  : Audit message (security) sent.
2023-04-12T08:43:24.366+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.s.a.l.services.SecurityAuditService  : Req or Resp body object is null. Not applying filters.
2023-04-12T08:43:24.369+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.s.a.l.services.SecurityAuditService  : Sending verbose Audit Message to exchange [mt.vf.audit.app.x] and routing key [mt.vf.audit.app.q].
2023-04-12T08:43:24.369+02:00  INFO [stock-management-service,,] 19504 --- [nio-8081-exec-4] m.c.s.a.l.services.SecurityAuditService  : Audit message (verbose) sent.

请注意,LoggingFilter类很好地打印了HTTP B3跟踪头;然而,Spring不会记录trace和span ID。这也不是线程问题,因为所有事情都发生在同一个线程中。
我们现在回到Sping Boot 2和Sleuth,因为有跟踪和跨度ID是必不可少的。但是如果有人能解释一下可能发生的事情,那将不胜感激。
编辑:经过大量的调试,发现ThreadLocal holds holds一个为null的TraceContext,但这仍然没有解决我的问题。

zzzyeukh

zzzyeukh1#

最终我设法解决了这个问题。额外的日志记录发生在一个用@Order(Ordered.HIGHEST_PRECEDENCE)注解的Filter中。因此,这个过滤器在ServerHttpObservationFilter之前运行,ServerHttpObservationFilter负责注入跟踪上下文。
解决方案是删除@Order注解,并添加@AutoConfiguration(after = ServerHttpObservationFilter.class),以确保日志过滤器在跟踪上下文可用后运行。

相关问题