[spring-projects/spring-boot]Spring Boot Webflux 应用程序中的 Reactor Netty 生成带有 CancelledServerWebExchangeException 异常和 UNKNOWN 结果的指标，但实际上没有问题

我创建了示例 repo 来重现此问题：https://github.com/MBalciunas/spring-webflux-netty-metrics-issue

这看起来像是 #29599 的重复。希望这个问题的结果是什么？

它不是#29599的重复，因为该问题与 UNKNOWN 指标的状态有关。在此票证中，我提出了一个问题，即结果 = UNKNOWN 和异常 = CancelledServerWebExchangeException 似乎是由指标生成的，可能没有明显的原因。正如我在示例描述中提供的那样，这只发生在 Netty 上，而不是 tomcat 上。因此，我希望的结果是，当任何地方都没有问题时，不再有 UNKNOWN 指标，或者如果这是正确的行为，则给出答案。如果是这样，为什么会发生这种情况，而看起来不应该发生。

CancelledServerWebExchangeExceptionTomcat 不会发生这种情况，因为客户端关闭连接时不会通知 Servlet 容器。使用 Servlet 容器时，只有服务器无法写入客户端时才会收到错误。这解释了为什么使用 Reactor Netty 而不是 Tomcat 会获得此指标。

当客户端过早关闭连接时，会产生此指标。从框架的角度来看，我们无法知道客户端是否因为响应时间过长而取消了呼叫，或者中间网络设备是否有故障。这就是我们outcome=UNKNOWN为此使用标签的原因。从这个角度来看，我们正在为您可能感兴趣的事件发出数据。另一种方法是，我们完全忽略指标中的这些请求，但如果他们正在追踪实际问题并且没有这些请求的数据，有些人会认为这是一个错误。

我很高兴能改善这种情况。有什么建议吗？

注意：如果我没记错的话，apache bench 会为每个请求打开和关闭一个连接（可以说，这是一种奇怪的基准测试方法）。从服务器的角度来看，像这样在本地对 TCP 层进行基准测试可能解释了为什么某些连接可能在交换完成之前就关闭了。

刚刚尝试了@MBalciunas 提供的一个例子，对我来说是一样的。 ab报告称所有 15k 个请求都非常成功，但在 spring actuar 端点有 454 个失败的请求，出现异常：CancelledServerWebExchangeException

ab -n 15000 -c 50 -H "Authorization:Basic cHJvbWV0aGV1czpwcm9tZXRoZXVz" http://localhost:8080/v1/hello
This is ApacheBench, Version 2.3 <$Revision: 1901567 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 1500 requests
Completed 3000 requests
Completed 4500 requests
Completed 6000 requests
Completed 7500 requests
Completed 9000 requests
Completed 10500 requests
Completed 12000 requests
Completed 13500 requests
Completed 15000 requests
Finished 15000 requests

Server Software:        
Server Hostname:        localhost
Server Port:            8080

Document Path:          /v1/hello
Document Length:        5 bytes

Concurrency Level:      50
Time taken for tests:   127.981 seconds
Complete requests:      15000
Failed requests:        0
Total transferred:      4440000 bytes
HTML transferred:       75000 bytes
Requests per second:    117.20 [#/sec] (mean)
Time per request:       426.604 [ms] (mean)
Time per request:       8.532 [ms] (mean, across all concurrent requests)
Transfer rate:          33.88 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   1.1      0      27
Processing:    73  425 112.1    430     880
Waiting:       73  425 112.1    430     880
Total:         73  426 112.1    430     880

Percentage of the requests served within a certain time (ms)
  50%    430
  66%    468
  75%    494
  80%    511
  90%    558
  95%    603
  98%    658
  99%    694
 100%    880 (longest request)

http_server_requests_seconds_count{exception="CancelledServerWebExchangeException",method="GET",outcome="UNKNOWN",status="200",uri="/v1/hello",} 454.0
http_server_requests_seconds_sum{exception="CancelledServerWebExchangeException",method="GET",outcome="UNKNOWN",status="200",uri="/v1/hello",} 197.189522582
http_server_requests_seconds_count{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/v1/hello",} 14651.0
http_server_requests_seconds_sum{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/v1/hello",} 6204.099123688

而且指标总数大于请求数似乎很奇怪。

requests: 15000.
SUCESS + UNKNOWN outcomes sum: 454.0 + 14651.0 = 15105.

我想重点讨论一下这里讨论的问题：在客户端过早关闭连接的情况下，当前的行为有什么不正确？预期​​的行为是什么？

请注意，apache bench 通常不被认为是一种基准测试工具，在这种情况下，它甚至没有使用 keep-alive 功能。

我尝试了另一个基准测试工具wrk。 wrk -t12 -c100 -d15s -H "Authorization: Basic cHJvbWV0aGV1czpwcm9tZXRoZXVz" http://localhost:8080/v1/hello

http_server_requests_seconds_count{exception="CancelledServerWebExchangeException",method="GET",outcome="UNKNOWN",status="200",uri="UNKNOWN",} 95.0
http_server_requests_seconds_count{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/v1/hello",} 1455.0

12 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   934.85ms  182.49ms   1.96s    75.72%
    Req/Sec    10.41      7.29    50.00     69.66%
  1491 requests in 15.03s, 430.99KB read
Requests/sec:     99.23
Transfer/sec:     28.68KB

即使没有错误或客户端关闭的迹象，仍然会收到大量未知的响应。

考虑到存在过早关闭连接的情况，这样的行为是正常的。但我们没有看到任何迹象表明连接取消次数接近指标所显示的数字，这就是为什么这些指标似乎没有反映现实。

所以您认为 weblux/netty 指标方面不可能出现一些错误/问题？

通过您最近的测试，是否仍然没有 Spring Security 就无法重现这种行为？

没有 Spring Security：

Running 30s test @ http://localhost:8080/v1/hello
  12 threads and 12 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.06ms    6.74ms 142.67ms   97.99%
    Req/Sec     3.65k     0.98k    9.92k    82.22%
  1303702 requests in 30.02s, 103.19MB read
Requests/sec:  43432.94
Transfer/sec:      3.44MB

http_server_requests_seconds_count{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/v1/hello",} 1303702.0 并且没有未知的结果。

@MBalciunas 谢谢 - 我正在与内部安全团队联系。对我来说，由于凭证检查预计会花费时间/CPU 资源，因此预计会出现额外的延迟。但在这种情况下，我对取消行为并不熟悉。一旦了解更多信息，我会在这里报告。

在联系安全部门并进一步测试后，我们有了更新信息。

安全团队的一位同事无法在他们的（更强大的？）机器上重现该问题。无论如何，我认为这与 Spring Security 无关。我认为当涉及安全性时，这种行为更容易重现，因为请求处理需要更长的时间，因为我们在各处创建新会话。

我通过在测试控制器方法中添加人工延迟，仔细地重现了这种行为，但没有涉及 Spring Security，如下所示：

@GetMapping("/")
public Mono<String> test() {
    return Mono.just("Spring Framework").delayElement(Duration.ofSeconds(5));
}

取消信号总是在基准测试运行结束时发出。我认为，发生这种情况的原因是基准测试工具正在发送大量并发请求，并在达到所选数量/持续时间时停止，然后取消当时所有剩余的进行中的请求。这解释了为什么基准测试报告和指标计数中的请求计数不一样。wrk 维护人员也报告说这是预期行为。

当使用处于调试模式的应用程序长时间运行基准测试时，指标过滤器中的断点仅在基准测试结束时才会到达。我认为这解释了我们在这里看到的行为。除非有另一个数据点可能导致我们在 Spring 或 Reactor 中出现错误，否则我认为深入研究您的生产用例并了解这些客户端断开连接可能来自何处会很有趣。

客户端（甚至）是否可能WebClient使用分散-聚集模式，其中一个远程调用出现问题会导致其他调用被取消？也许客户端正在使用主要/后备机制，其中主服务在特定时间限制内没有响应，客户端取消连接并使用后备响应？（想想 Resilience4J 和其他）。如果某些端点特别容易看到这些取消，我认为这将支持这一理论。

回到实际记录的指标，如果您有改进这部分的想法，请告诉我。从我的角度来看，结果"UNKNOWN"和异常名称与正在发生的事情一致：客户端消失了，我们不知道原因。我认为抑制这些指标不会有太大的好处，因为我们可以隐藏真正问题的症状。将来，Servlet 容器可能会提供此信息，并且服务器之间的体验将更加一致。

在使用其他 kotlin 服务 java.net.http.HttpClient 请求对示例端点进行本地测试之后，结果如下：

1ms delay in endpoint
http_server_requests_seconds_count{exception="CancelledServerWebExchangeException",method="GET",outcome="UNKNOWN",status="200",uri="/v1/hello",} 199.0
http_server_requests_seconds_count{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/v1/hello",} 99827.0
responses:
    status:{200=100000}
    message:{Hello=100000}

no delay, but loop with print in endpoint
http_server_requests_seconds_count{exception="CancelledServerWebExchangeException",method="GET",outcome="UNKNOWN",status="200",uri="/v1/hello",} 91.0
http_server_requests_seconds_count{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/v1/hello",} 99923.0
responses:
    status:{200=100000}
    message:{Hello=100000}

no delay in endpoint
http_server_requests_seconds_count{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/v1/hello",} 100000.0
responses:
    status:{200=100000}
    message:{Hello=100000}

没有迹象表明客户端取消，并且这些未知指标始终被记录，而不仅仅是在最后。因此，基于此，问题似乎与我们的生产服务或延迟时间无关，因为 1ms 延迟不应该有这样的影响。

我认为我们在这里没有取得进展；我们正在根据每条评论更改“负载测试”基础结构，并且我们正在花时间做一些对您的问题毫无用处的事情。在我看来，只有三种方法可以解决这个问题：

1. 您认为这些CancelledServerWebExchangeException对您的应用程序来说只是噪音并且会分散注意力；在这种情况下，您可以MeterFilter在应用程序中贡献一些来过滤掉它们。
2. 在某些情况下，你会发现此链中的某些行为不正常：Netty（发送有关客户端断开连接的通道事件）-> Reactor Netty（取消反应管道）-> Spring Boot（将此信号转换为指标）。如果您使用本地负载测试设置，您可能会在其中一个或甚至在本地 TCP 堆栈中发现错误；这里的可能性很低，即使你这样做了，这也可能是你在生产中看到的问题。
3. 你设法从生产中收集有关客户端断开连接的数据（配置 Netty 或 Reactor Netty 的调试日志、网络流量捕获），并真正理解为什么在生产中会看到这种情况

与此同时，我将关闭此问题，因为我没有理由现在花更多时间在这个问题上。